데이터베이스 시스템을 운영하면서 성능 개선은 매우 중요한 일입니다.
CUBRID는 다른 DBMS와 다르게 JDBC 드라이버-브로커-데이터베이스 서버의 3계층(3-tier) 구조로 구성되어 있습니다.
3계층 중 브로커는 서버와 외부 응용 프로그램 간의 통신을 중계하는 CUBRID 전용 미들웨어로서, 커넥션 풀링, 모니터링, 로그 추적 및 분석 기능을 제공합니다. CUBRID는 CUBRID BROKER프로세스가 생성한 SQL LOG파일을 통해 SQL 성능 분석을 할 수 있습니다. (다른 DBMS 성능 모니터링은 시스템 DMV를 조회하여 확인합니다.)
이번 블러그에서는 CUBRID BROKER가 생성한 SQL LOG 파일을 이용하여 성능 문제를 분석하고 개선하는데 유용한 유틸리티에 대해 3회에 걸쳐 소개할 예정이며, 첫번째로 소개할 유틸리티는 broker_log_top 입니다.
▣ broker_log_top
broker_log_top 유틸리티는 수행 시 특정 기간 동안 생성된 SQL LOG 파일를 분석하여 실행 시간이 긴 순서대로 나열합니다. 이 유틸리티는 수행시 log_top.res와 log_top.q와 같이 2개의 결과 파일을 남깁니다.
log_top.res 파일에는 특정기간 동안 수행된 SQL들에 대한 최대 수행 시간, 최소 수행 시간, 평균 수행 시간 및 수행 횟수(에러 발생 횟수)이 저장됩니다.
log_top.q 파일에는 log_top.res에 나열된 질의 번호에 해당되는 SQL 문장이 저장됩니다.
해당 유틸리티의 실행 방법은 다음과 같습니다.
위에서 sql_log_file_list는 CUBRID BROKER 프로세스가 생성한 SQL LOG파일을 지칭합니다.
SQL 로그 파일은 응용 클라이언트가 요청하는 SQL을 기록하며 <broker_name>_<app_server_num>.sql.log 라는 이름으로 저장합니다. SQL 로그는 SQL_LOG 파라미터 값이 ON(기본값)인 경우에만 생성됩니다. 기본값 설정이라면 $CUBRID/log/broker/sql_log 디렉터리에서 해당 파일들을 확인할 수 있습니다..
BROKER 상태를 조회하여 확인 할 수 있으며 확인 방법은 다음과 같다.
이제 유틸리티를 실행을 해 보겠습니다.
query_editor_1.sql.log
query_editor_2.sql.log
query_editor_3.sql.log
print results...
$ ls
log_top.q log_top.res query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log
위 결과 화면처럼 log_top.q파일과 log_top.res 파일이 생성 되었습니다.
단, Windows에서는 *.sql.log가 인식되지 않으므로 아래 화면 처럼 공백 구분자와 함께 대상 파일을 모두 나열해야 합니다.
query_editor_1.sql.log
query_editor_2.sql.log
query_editor_3.sql.log
print results...
이제 결과 파일인 log_top.res 파일을 살펴보겠습니다.
max min avg cnt(err)
-----------------------------------------------------
[Q1] 0.013 0.010 0.011 3 (0)
[Q2] 0.013 0.013 0.013 1 (0)
[Q3] 0.010 0.009 0.009 2 (0)
[Q4] 0.003 0.003 0.003 3 (0)
[Q5] 0.002 0.002 0.002 3 (0)
[Q6] 0.002 0.002 0.002 2 (0)
[Q7] 0.001 0.000 0.000 48 (0)
[Q8] 0.001 0.000 0.000 3 (0)
질의 번호 [Q1]은 3회가 수행되었으며 동일 SQL의 에러로 인한 실행 실패 횟수는 없으며 수행 시간은 최대 0.013초가 걸렸고 최소 0.010초, 평균 0.011초가 걸린 것을 알 수 있습니다.
예제로 위의 실제 운영된 특정 시스템의 SQL 구문의 log_top.res 결과입니다.
[Q1]이 가장 느린 것으로 표현 되어 있으나 평균 0.172 초 걸린 SQL이므로 순간적 잠금 현상이 발생 했었을 것을 추측 할 수 있습니다. 그러나 [Q2], [Q3]의 경우에는 평균 2.116초, 4.342초 이고 수행 횟수도 많았기 때문에 튜닝이 필요 한 대상 SQL 이 될 수 있습니다. 따라서, 수행 횟수가 많으며 평균 속도가 느린 SQL 구문은 튜닝 대상이며, 평균 속도는 빠르나 특정 시점에 느려진 SQL은 일시적 잠금 현상에 의한 것이므로 트랜잭션 경합을 조사 해 보아야 합니다.
이제 log_top.q 파일의 내용을 살펴보겠습니다.
[Q1]-------------------------------------------
query_editor_1.sql.log:56
17-12-27 19:01:19.641 (2) execute srv_h_id 1 SELECT a.attr_name, a.attr_type, a.from_class_name, a.data_type, a.prec, a.scale, a.is_nullable, a.domain_class_name, a.default_value, a.def_order, c.is_system_class, c.class_type, c.partitioned, c.owner_name, c.class_name, a.from_attr_name, c.is_reuse_oid_class FROM db_attribute a, db_class c WHERE c.class_name=a.class_name ORDER BY a.class_name, a.def_order
17-12-27 19:01:19.655 (2) execute 0 tuple 342 time 0.013
[Q2]-------------------------------------------
query_editor_1.sql.log:1218
17-12-27 19:10:50.189 (90) execute srv_h_id 1 commit;
17-12-27 19:10:50.203 (90) execute 0 tuple 0 time 0.013
[Q3]-------------------------------------------
query_editor_1.sql.log:599
17-12-27 19:01:33.509 (44) execute srv_h_id 1 SELECT c.class_name, COUNT(*) AS count_column, CAST(SUM( CASE WHEN "data_type" = 'BIGINT' THEN 8.0 WHEN "data_type" = 'INTEGER' THEN 4.0 WHEN "data_type" = 'SMALLINT' THEN 2.0 WHEN "data_type" = 'FLOAT' THEN 4.0 WHEN "data_type" = 'DOUBLE' THEN 8.0 WHEN "data_type" = 'MONETARY' THEN 12.0 WHEN "data_type" = 'STRING' THEN a.prec WHEN "data_type" = 'VARCHAR' THEN a.prec WHEN "data_type" = 'NVARCHAR' THEN a.prec WHEN "data_type" = 'CHAR' THEN a.prec WHEN "data_type" = 'NCHAR' THEN a.prec WHEN "data_type" = 'TIMESTAMP' THEN 8.0 WHEN "data_type" = 'DATE' THEN 4.0 WHEN "data_type" = 'TIME' THEN 4.0 WHEN "data_type" = 'DATETIME' THEN 4.0 WHEN "data_type" = 'BIT' THEN FLOOR(prec / 8.0) WHEN "data_type" = 'BIT VARYING' THEN FLOOR(prec / 8.0) ELSE 0 END ) AS BIGINT) AS size_column, SUM( CASE WHEN "data_type" = 'STRING' THEN 1 WHEN "data_type" = 'VARCHAR' THEN 1 WHEN "data_type" = 'NVARCHAR' THEN 1 WHEN "data_type" = 'NCHAR' THEN 1 WHEN "data_type" = 'BIT VARYING' THEN 1 ELSE 0 END ) AS size_over_column, MAX(c.class_type) AS class_type, MAX(c.partitioned) AS partitioned FROM db_class c, db_attribute a WHERE c.class_name = a.class_name AND c.is_system_class = 'NO' AND c.class_type = 'CLASS' AND a.from_class_name IS NULL GROUP BY c.class_name
17-12-27 19:01:33.518 (44) execute 0 tuple 11 time 0.010
[Q4]-------------------------------------------
query_editor_1.sql.log:1392
17-12-27 20:33:38.058 (109) execute_all srv_h_id 1 SELECT a.class_name, a.attr_name, a.attr_type, a.data_type, a.prec, a.scale FROM db_attr_setdomain_elm a WHERE a.class_name = ? ORDER BY a.class_name, a.attr_name
17-12-27 20:33:38.058 (109) bind 1 : VARCHAR (5)code
17-12-27 20:33:38.059 (109) execute_all 0 tuple 0 time 0.010
각 질의 번호에 대한 SQL 문장이 추출되며 동일 SQL 중 가장 느린 질의가 발췌되고 변수 바인딩을 사용한 경우 바인딩 변수의 순서에 따른 매핑 값까지 알 수 있습니다. 질의 번호 [Q4] 의 SQL 문장은 query_editor_1.sql.log 파일의 1,392번째 라인에 있는 SQL 문장이 추출 된 것이고 해당 세션에서 109번째 수행된 SQL임을 알 수 있습니다.
이번에는 -t 옵션을 사용하여 각 트랜잭션 별로 SQL LOG 파일을 추출을 해 보겠습니다.
트랜잭션별 SQL LOG 파일을 추출하는 이유는 log_top.res, log_top.q 파일에 생성 된 정보는 개별 SQL구문에 대한 시간만 측정되어 있으므로 예외 될 수 있는 사항(잠금에 의한 일시적 느려진 SQL)을 고려하기 위한 것입니다.
query_editor_1.sql.log
query_editor_2.sql.log
query_editor_3.sql.log
$ ls
log_top.q log_top.res log_top.t query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log
위와 같이 log_top.t 파일이 생성되는 것을 볼 수 있으며, vi 등으로 파일을 확인할 수 있습니다.
첫번째, 트랜잭션 정보를 보면 최초 업데이트 이후 트랜잭션이 닫히지 않고 유지되며 WAS에서 health 체크 SQL 구문이 수차 례 수행되었고 마지막에 다시 업데이트 구문이 실행되면서 TCL구문이 수행되어 해당 트랜잭션이 완료 되었습니다.
이 예제에서의 시사하는 점은 code 테이블에 f_name 컬럼에 인덱스가 없었다고 가정하면 약 32초간 code 테이블에 접근한 다른 트랜잭션의 특정 DML 구문은 테이블 잠금 해제 상태가 될 때까지 대기하여 code 테이블의 동시성이 저하 되었었음을 알 수 있습니다.
두번째, SQL 구문이 수행된 후 COMMIT이 약 20초간 들어오지 않았음을 알 수 있습니다.
broker_log_top 유틸리티에는 다수의 SQL LOG 파일을 분석 시 특정 시간대만 추출도 가능한 추가 옵션도 설정 가능합니다.
해당 옵션 및 자세한 설명은 매뉴얼의 CUBRID 운영 > CUBRID 프로세스 제어의 브로커 설정 정보 확인 중 SQL 로그 관리 중 broker_log_top https://www.cubrid.org/manual/en/10.1/admin/control.html#broker-log-top 을 참고하시기 바랍니다.
다음에는 SQL LOG 파일을 이용하여 지난 상황을 재현해 볼 수 있는 cubrid_replay에 대해서 소개하겠습니다.
