쿼리 로그를 읽는 방법

Henry Hwang -

다음과 같이 이미 쿼리 로깅에 관한 몇 가지 문서가 있습니다.

그러나, 우리는 쿼리 로그 항목을 이해하고 오래 실행되는 쿼리를 식별하는 방법에 대해 중점적으로 다룰 것입니다.

왜 그래야 하죠?

UI는 잠재적 쿼리 문제를 찾아내고 과거 이력 비교를 수행하기에 유용하지만, 쿼리 로그를 검토하면 UI에 나타나지 않는 문제를 발견할 수 있습니다. 

쿼리 로그

기본적으로 ClustrixDB 로그는 다음 디렉토리에 있습니다.

/data/clustrix/log

각 쿼리 항목은 타임스탬프가 지정되며 다음과 같이 분류됩니다.

  • SLOW: 쿼리 실행 시간이 전역 변수 session_log_slow_threshold_ms 값(기본값은 20000ms 입니다)을 초과했습니다. 기본적으로 전역 변수 session_log_slow_queries로 활성화 되어 있음.
  • DDL: 쿼리가 DDL(CREATE, DROP, ALTER)이거나 SET GLOBAL입니다. 기본적으로 전역 변수 session_log_ddl로 활성화 되어 있음.
  • BAD: 쿼리가 반환된 행보다 더 많은 행을 읽습니다. 이는 나쁜 플랜 또는 누락된 인덱스를 나타낼 수 있습니다. 기본적으로 전역 변수 session_log_bad_queries로 비활성화 되어 있음.
  • SQLERR: 구문 오류, 시간 초과, 퍼미션(permission) 거부 등. 기본적으로 전역 변수 session_log_bad_queries로 활성화 되어 있음. 

전역 변수

쿼리 로깅은 다음 전역 변수에 의해 제어됩니다(기본값이 표시됨):

mysql> show global variables like 'session_log%';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| session_log_bad_queries        | false |
| session_log_bad_read_ratio     |   100 |
| session_log_bad_read_threshold |  4000 |
| session_log_ddl                |  true |
| session_log_error_queries      |  true |
| session_log_slow_queries       |  true |
| session_log_slow_threshold_ms  | 20000 |
+--------------------------------+-------+
7 rows in set (0.00 sec)

v5.2 이상에서는 값을 보다 쉽게 식별할 수 있도록 측정 단위가 변수 및 필드 이름에 추가되었습니다. 예를 들어, 전역 변수session_log_slow_threshold_ms는 v5.2 이전에 session_log_slow_threshold로 불렸습니다.

쿼리 로그 항목

각 쿼리 로그 항목은 다음과 같은 정보로 구성됩니다.

[timestamp] [nodename] [process name] [category] [SID] [db] [user] [ac] [xid] [sql] [status] [execution time] [reads] [inserts] [deletes] [updates] [counts] [rows_read] [forwards] [rows_output] [semaphore_matches] [runtime] [attempts]

  • Timestamp: 시간대를 나타냅니다. 모든 노드에서 시간을 동기화하는 것이 매무 중요합니다.
  • Hostname: 항목이 로깅된 노드의 이름.
  • Process name: Clustrix 프로세스 이름, "clxnode". 레거시 어플라이언스에서는 "real"로 표시됩니다.
  • Category: 로그에서 항목의 유형. SLOW, DDL, BAD 또는 SQLERR.
  • SID: 세션 ID. 로깅된 쿼리를 가지고 특정 세션을 식별할 때 유용합니다.
  • DB: 쿼리가 실행된 데이터베이스 이름.
  • User: 쿼리를 실행하는 유저(User). SBR(statement-based replication)를 사용하는 경우, 마스터에서 넘어온 문장의 문제를 해결할 때 복제 계정을 검색할 수 있습니다.
  • AC: 자동 커밋(auto-commit). 이는 쿼리가 명시적 트랜잭션인지 여부를 판별하는 데 유용합니다. DDL은 명시적 트랜잭션에 있지 않더라도 모두 ac=N이 됨에 주의하십시오.
  • XID: 트랜잭션 ID. 잠금 문제를 해결할 때 세션을 XID에 연결하는데 유용합니다.
  • SQL: 쿼리가 4KB 문 버퍼를 초과하지 않는 경우 전체 쿼리. logger는 쿼리 중간에 줄임표를 넣고 4KB 제한에 맞추기 위해 쿼리의 일부를 제거합니다.
  • Status: 영향받은 행수 또는 에러 메시지와 같은 쿼리 결과.
  • Time: 쿼리가 수신되어, 컴파일 및 처리되어 결과를 리턴할 때까지 걸린 시간. SLOW 쿼리에 대해 확인할 수 있는 시간.

나머지는 일부 문제 해결에 중요한 내부 카운터입니다.

예제 로그 항목

다음은 일부 예제 로그 항목입니다.

2014-04-28 00:00:00.630935 UTC 2014 clxnode001 clxnode: INSTR SLOW SID:3756073989 db=test user=user1@192.168.0.100 ac=Y xid=535eff740597800a sql="delete from test_tbl" [Ok: 1103697 rows deleted] time 220365.5ms; reads: 1103700; inserts: 3311091; deletes: 6622182; updates: 0; counts: 1103697; rows_read: 2207394; forwards: 9933282; rows_output: 2; semaphore_matches: 0; runtime: 80800528947; attempts: 1

2014-04-28 00:00:05.918485 UTC 2014 clxnode001 clxnode: INSTR DDL SID:3751805957 db=#undef user=root@localhost ac=N xid=535eff796dffe80a sql="trim binlog `binlogtest` before file 'binlogtest.010086'" [no error] time 1236.3ms; reads: 0; inserts: 0; deletes: 0; updates: 0; counts: 0; rows_read: 0; forwards: 0; rows_output: 0; semaphore_matches: 0; runtime: 0; attempts: 1

2014-04-28 00:00:00.988627 UTC 2014 clxnode001 clxnode: INSTR SQLERR SID:3737319429 db=test user=user2@192.168.0.101 ac=Y xid=535eff74fac4780a sql="SELECT ID INTO ID_Rule FROM test2_tbl WHERE ID = ID2" [NOT FOUND] time 0.7ms; reads: 3; inserts: 1; deletes: 0; updates: 0; counts: 0; rows_read: 4; forwards: 3; rows_output: 2; semaphore_matches: 0; runtime: 84060; attempts: 1

2014-04-28 00:01:06.780817 UTC 2014 clxnode001 clxnode: INSTR BAD SID:3737319429 db=test user=user2@192.168.0.101 ac=Y xid=535effb51a2a580a sql="SELECT IFNULL(ID, 0) AS ID, COL2, IFNULL(DATE1,'2014-01-01'), IFNULL(COL4, 0), IFNULL(Code,''), IFNULL(Date2, '2050-01-01'), IFNULL(Date3,'2014-01-01'), IFNULL(Col8, '') FROM test3_tbl WHERE ID = OtherID" [Ok: 1 rows selected] time 1672.7ms; reads: 3; inserts: 1; deletes: 0; updates: 0; counts: 1; rows_read: 1485493; forwards: 4; rows_output: 3; semaphore_matches: 0; runtime: 1119399218; attempts: 1

의견

위 예제 항목에서 수집된 의견

  • 첫 번째 쿼리(delete from test_tbl)는 1103697 행을 삭제하는데 220초(220365.5ms로 기록됨)가 걸렸기 때문에 SLOW로 로깅되었습니다. 복제 슬레이브 지연 문제를 해결할 때, 대규모 쓰기가 슬레이브 지연의 원인으로 의심되는 경우 마스터 쿼리 로그에서 대량의 "행 삭제" 또는 "행 업데이트"를 찾아야 할 수 있습니다.
  • 두 번째 로그 항목의 ac=N은 trim binlog가 DDL이지만 START TRANSACTION 또는 BEGIN으로 시작할 때 다른 문(statements)도 명시적 트랜잭션이 될 수 있습니다..
  • 항목 3과 4 는 동일한 세션 ID를 가진 동일한 세션에서 발생한 쿼리입니다.

로그 항목 수집

분산 데이터베이스에서는 각 노드가 처리중인 내용만 기록하므로 오래동안 실행되는 쿼리를 식별하기 위해 모든 노드의 쿼리를 조사해야 합니다.

일반적으로 한 위치에서 로그 항목을 사용하는 것이 더 쉽기 때문에 clx 유틸리티를 사용하여 보다 쉽게 작업할 수 있습니다.

다음은 항목을 수집하기 위해 실행할 수 있는 예제입니다. 로그 파일 이름과 날짜/시간을 적절히 바꿉니다.

cd /data/clustrix/  # or some other location like /tmp that has sufficient space
/opt/clustrix/bin/clx cmd 'grep "^[today's date]" /data/clustrix/log/query.log' > q.log.todaysdate

느린 쿼리 식별

위에서 추출한 쿼리 로그를 사용하여 실행 시간이 긴 쿼리를 파싱하여 다음을 수행할 수 있습니다.


export TMPDIR=/clustrix  # For the appliances, you may want to set TMPDIR to /clustrix.
cat q.log.todaysdate.uc | sed 's/^.*time \([0-9]*\).*$/\1 \0/' | sort -rn > longrunningq.todaysdate

가장 오래 실행되는 쿼리는 출력 파일의 맨에 있습니다. 다음은 오래 걸리는 쿼리에 대한 쿼리 로그를 처리한 후의 출력 예입니다.

103166 Jul 11 17:47:58.330347 UTC 2014 clxnode1 real: INSTR SLOW SID:2464620545 db=test user=user1@192.168.0.1 ac=Y xid=53c1881e3c271802 sql="select col1, col2, col3, col4, col5, col6, col7, col8, col9 from tbl12 where col1>25 and col2=0 and col3<>200" [Ok: 0 rows selected] time 103166.3ms; reads: 5; inserts: 1; deletes: 0; updates: 0; counts: 0; rows_read: 1154141; forwards: 5; rows_output: 2; semaphore_matches: 0; runtime: 4921071027; attempts: 1
58055 Jul 11 17:25:39.453805 UTC 2014 clxnode1 real: INSTR SLOW SID:2464048129 db=test user=user1@192.168.0.1 ac=Y xid=53c1831077c1f802 sql="select col1, col2, col3, col4, col5, col6, col7, col8, col9, col10, col11, col12, col13 from tbl2 where col1 like '123456' and date(col2) = '2014-07-11'" [Ok: 0 rows selected] time 58055.0ms; reads: 5; inserts: 1; deletes: 0; updates: 0; counts: 0; rows_read: 11797794; forwards: 5; rows_output: 2; semaphore_matches: 0; runtime: 40765655404; attempts: 1
55666 Jul 11 17:46:10.868463 UTC 2014 clxnode1 real: INSTR SLOW SID:2445069313 db=test user=user1@192.168.0.1 ac=Y xid=53c187e245f42002 sql="select col1, col2, col3, col4, col5, col6, col7, col8, col9, col10, col11, col12, col13, col4, col15, col16, col17, col18, col19, col20, col21, col22, col23, col24, col25, col26, col27, col28, col29, col30, col31, col32, col33, col34, col35, col36, col37, col38, col39, col40, col41, col42, col43, col44, col45, col46, col47, col48, col49, col50, col51, col52, col53, col54, col55, col56, col57 from tbl3 where col1='1234567'" [Ok: 1 rows selected] time 55666.1ms; reads: 5; inserts: 1; deletes: 0; updates: 0; counts: 1; rows_read: 11798489; forwards: 6; rows_output: 3; semaphore_matches: 0; runtime: 125292702595; attempts: 1

 

오래 걸리는 쿼리를 식별한 후에 쿼리가 왜 느려지는지 결정해야 합니다. 이것에 대한 여러 가지 이유가 있을 수 있습니다.

  • 과도한 시스템 로드
  • 고르지 못한 데이터 분포
  • 누락된 인덱스
  • 네트워크 지연

이후 포스팅에서 이들 주제에 대해 다룰 예정입니다.

모범 사례

UI 및 쿼리 로그 처리를 모두 사용하여 가능한 성능 문제의 원인을 식별하는 것이 가장 좋습니다.

매일 밤 실행되는 크론(cron) 작업을 구성하여 SLOW, BAD 및 SQLERR 항목에 대한 전날의 쿼리 로그 항목을 수집 및 파싱하고 애플리케이션이나 사용자가 클러스터에 성능이 좋지 않는 쿼리를 로딩하고 있지는 않은지 확인하도록 매일 검토해야 합니다 성능이 좋지 않은 쿼리를 수정하면 시스템 리소스가 더 많은 쿼리를 처리하고 클러스터의 응답 속도가 향상됩니다.

또 다른 질문이 있으십니까? 문의 등록

0 댓글

댓글을 남기려면 로그인하세요.
Zendesk 제공