SQL 쿼리 프로파일링
SQL 쿼리 프로파일링 (Profiling SQL Queries)
이 문서는 SQLite가 SQL 쿼리를 프로파일링하는 방법을 설명해요. 이 기능은 기본적으로 켜져 있지 않으며, 특정 컴파일 옵션으로 활성화한 후 명령줄 셸의 .scanstats 명령으로 사용할 수 있어요.
출처: 문서
본문
SQLite에는 SQL 쿼리를 프로파일링하는 내장 지원이 있지만, 기본적으로는 활성화되어 있지 않아요. 쿼리 프로파일링을 활성화하려면 SQLite를 다음 옵션으로 컴파일해야 해요.
-DSQLITE_ENABLE_STMT_SCANSTATUS
이 옵션으로 SQLite를 빌드하면 다양한 프로파일링 지표에 접근할 수 있는 sqlite3_stmt_scanstatus_v2() API가 활성화돼요. 이 페이지의 나머지 부분은 그 지표들을 사용해 SQLite 명령줄 셸이 생성하는 프로파일링 보고서를, API 자체보다는 보고서 중심으로 설명해요.
셸이 생성하는 프로파일링 보고서는 EXPLAIN QUERY PLAN 명령이 생성하는 쿼리 계획 보고서와 매우 유사해요. 이 문서는 독자가 이 형식에 익숙하다고 가정해요.
위 옵션으로 컴파일된 명령줄 셸에서는 다음 명령으로 쿼리 프로파일링을 활성화해요.
sqlite> .scanstats on
활성화하면 셸은 각 SQL 쿼리가 실행된 뒤 자동으로 쿼리 프로필을 출력해요. .scanstats off로 끌 수 있어요. 예를 들어:
sqlite> .scanstats on
sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e;
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 255M 100% 1 3
|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) 60.0M 23% 1 3
`--SCAN t2 134M 52% 3 150K
간단한 경우 - Rows, Loops, Cycles
다음 스키마를 가진 데이터베이스를 생각해 보아요.
CREATE VIRTUAL TABLE ft USING fts5(text);
CREATE TABLE t1(a, b);
CREATE TABLE t2(c INTEGER PRIMARY KEY, d);
.scanstats on을 먼저 실행한 뒤:
sqlite3> SELECT * FROM t1, t2 WHERE t2.c=t1.a;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 1.14M 100%
|--SCAN t1 455K 40% 1 500
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 620K 54% 500 250
위 예제에서 <...query results...> 뒤의 텍스트는 방금 실행한 조인 쿼리에 대한 프로필 보고서예요. EXPLAIN QUERY PLAN 출력과 비슷한 부분은 쿼리가 "t1" 테이블을 전체 테이블 스캔하고, 방문한 각 행마다 "t2" 테이블을 INTEGER PRIMARY KEY로 조회한다는 뜻이에요.
"SCAN t1" 줄 오른쪽의 "Loops" 열 값 1은 이 루프(테이블 t1 전체 스캔)가 정확히 한 번 실행됐다는 뜻이에요. "Rows" 열 아래의 500은 그 한 번의 스캔이 500개의 행을 생성한다는 뜻이에요.
"SEARCH t2 USING ..." 줄의 "Loops"는 500인데, 이는 이 "루프"(실제로는 INTEGER PRIMARY KEY 조회)가 500번 실행됐다는 뜻이에요. "t1" 전체 스캔이 방문한 각 행에 대해 한 번씩 실행됐으니 타당해요. "Row" 아래의 250은 그 500번의 루프가 합쳐 250개의 행을 생성했음을 의미해요. 즉, 테이블 t2에 대한 INTEGER PRIMARY KEY 조회 중 절반만 성공했고, 나머지 절반은 찾을 행이 없었다는 뜻이에요.
SEARCH나 SCAN 항목의 루프 개수는 반드시 바깥 루프가 출력한 행 수와 일치하지는 않아요. 예를 들어 위 쿼리를 다음과 같이 바꾸면:
sqlite3> SELECT * FROM t1, t2 WHERE t1.b<=100 AND t2.c=t1.a;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 561K 100%
|--SCAN t1 345K 62% 1 500
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 129K 23% 100 50
이번에는 "SCAN t1" 루프가 여전히 500개의 행을 방문하지만, "SEARCH t2" 조회는 100번만 수행돼요. SQLite가 "t1.b<=100" 제약과 맞지 않는 t1의 행을 버릴 수 있었기 때문이에요.
"cycles" 측정값은 CPU time-stamp counter를 기반으로 하므로 벽시계 시간의 좋은 대리 지표예요. 위 쿼리의 총 사이클 수는 약 561,000이에요. (표시되는 모든 값은 유효숫자 3자리로 반올림됐어요.) 두 루프("SCAN t1..."과 "SEARCH t2...") 각각에 대해 사이클 수는 그 루프에 직접 귀속될 수 있는 작업에 소요된 시간을 나타내요. 구체적으로, 그 루프를 위해 데이터베이스 b-tree를 탐색하고 데이터를 추출하는 데 걸린 시간이에요. SQLite가 수행하는 다른 내부 작업은 어느 루프에도 직접 귀속되지 않으므로, 이 값들은 쿼리의 총 사이클과 정확히 더해지지는 않아요.
"SCAN t1" 루프의 사이클 수는 345K로 쿼리 총계의 62%였어요. "SEARCH t2" 루프가 수행한 100번의 조회는 129K 사이클(총계의 23%)이 걸렸어요.
가상 테이블을 사용할 때 "Rows"와 "Loops" 지표는 일반 SQLite 테이블의 루프와 같은 의미예요. "Cycles" 측정값은 그 루프와 연관된 가상 테이블 메서드 안에서 소비된 총 사이클이에요. 예를 들어:
sqlite3> SELECT * FROM ft('sqlite'), t2 WHERE t2.c=ft.rowid;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 836K 100%
|--SCAN ft VIRTUAL TABLE INDEX 0:M1 740K 91% 1 48
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 62.9K 8% 48 25
이 경우 fts5 테이블 "ft"에 대한 단일 쿼리(Loops: 1)가 48개의 행(Rows: 48)을 반환했고, 약 740K 사이클(전체 쿼리 시간의 약 88%)을 소비했어요.
복잡한 경우 - Rows, Loops, Cycles
앞 섹션과 같은 스키마를 사용해 더 복잡한 예를 보아요.
sqlite3> WITH cnt(i) AS (
SELECT 1 UNION SELECT i+1 FROM cnt WHERE i<100
)
SELECT
*, (SELECT d FROM t2 WHERE c=ft.rowid)
FROM
(SELECT count(*), a FROM t1 GROUP BY a) AS v1 CROSS JOIN
ft('sqlite'),
cnt
WHERE cnt.i=ft.rowid AND v1.a=ft.rowid;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 178M 100%
|--CO-ROUTINE v1
| |--SCAN t1 397K 0% 1 500
| `--USE TEMP B-TREE FOR GROUP BY
|--MATERIALIZE cnt 1.28M 1%
| |--SETUP
| | `--SCAN CONSTANT ROW
| `--RECURSIVE STEP
| `--SCAN cnt 129K 0% 100 100
|--SCAN v1 4.50M 3% 1 500
|--SCAN ft VIRTUAL TABLE INDEX 0:M1= 162M 91% 500 271
|--SCAN cnt 7.33M 4% 95 9500
`--CORRELATED SCALAR SUBQUERY 3 169K 0% 37
`--SEARCH t2 USING INTEGER PRIMARY KEY (rowid=?) 94.7K 0% 37 21
위 예제에서 가장 복잡한 부분은 쿼리 계획(보고서 중 EXPLAIN QUERY PLAN이 생성하는 부분)을 이해하는 것이에요.
다음 쿼리는 자동 인덱스와 외부 정렬을 사용해요.
sqlite> SELECT * FROM
t2,
(SELECT count(*) AS cnt, d FROM t2 GROUP BY d) AS v2
WHERE v2.d=t2.d AND t2.d>100
ORDER BY v2.cnt;
<...query results...>
Cycles Loops Rows
---------- ----- -----
QUERY PLAN 6.23M 100%
|--MATERIALIZE v2 2.35M 38%
| |--SCAN t2 188K 3% 1 250
| `--USE TEMP B-TREE FOR GROUP BY
|--SCAN t2 456K 7% 1 250
|--CREATE AUTOMATIC INDEX ON v2(d, cnt) 1.67M 27% 1 250
|--SEARCH v2 USING AUTOMATIC COVERING INDEX (d=?) 933K 15% 200 200
`--USE TEMP B-TREE FOR ORDER BY 662K 11% 1 200
흥미로운 점은 다음과 같아요.
- 이 쿼리는 서브쿼리를 임시 테이블로 구체화(materialize)한 뒤, 그 위에 자동(임시) 인덱스를 만들고, 그 인덱스로 조인을 최적화해요. "MATERIALIZE v2", "CREATE AUTOMATIC INDEX", "SEARCH ... USING AUTOMATIC INDEX" 이 세 단계 각각에 별도의 사이클 수가 있어요. "CREATE AUTOMATIC INDEX" 줄과 연관된 "rows"는 인덱스에 포함된 총 행 수를 나타내요. "SEARCH ... USING AUTOMATIC INDEX" 줄과 연관된 "loops"와 "rows"는 인덱스가 사용된 조회 횟수와 그 조회로 찾은 총 행 수를 나타내요.
- 외부 정렬 "USE TEMP B-TREE FOR ORDER BY"는 별도로 계산돼요. 사이클 수는 반환된 행을 정렬하는 데 소비된 추가 사이클(행을 임의 순서로 반환했을 때와 비교해)을 나타내요. rows 수는 정렬된 행의 개수를 나타내요.
플래너 추정치 (Planner Estimates)
.scanstats on으로 프로파일링을 켜고 .scanstats off로 끄는 것 외에도, 셸은 .scanstats est를 받아들여요.
sqlite> .scanstats est
이 명령은 쿼리 프로필의 "SCAN..." 및 "SEARCH..." 각 요소에 두 개의 추가 값을 포함하는 특별한 종류의 프로파일링 보고서를 활성화해요. "Loops"와 "Rows" 열은 각 단계의 실제 호출 횟수와 실제 생성된 행 수를 보여 주는데, 이제 두 숫자 모두 뒤에 쿼리 플래너가 알고리즘을 고를 때 사용한 그 양의 추정치가 붙어 나와요.
sqlite> SELECT a FROM t1, t2 WHERE a IN (1,2,3) AND a=d+e ORDER BY a;
<query results...>
Cycles Loops (est) Rows (est)
---------- ------------ ------------
QUERY PLAN 264M 100%
|--SEARCH t1 USING INTEGER PRIMARY KEY (rowid=?) 60.5M 23% 1 1 3 3
`--SCAN t2 139M 53% 3 1.24K 450K 3.12M
.scanstatus est 기능의 중요한 용도 중 하나는, 쿼리 플래너가 실제와 크게 다른 행 수 추정치를 기반으로 잘못된 선택을 할 때 개발자가 빠르게 알아차리도록 돕는 것이에요. 예를 들어 특정 조인이 행 수를 극적으로 줄였는데 플래너가 그것을 예측하지 못해 느린 조인 순서를 선택할 수 있어요. 이런 경우 .scanstats est로 실제 값과 추정치의 차이를 즉시 볼 수 있어요.
저수준 프로파일링 데이터 (Low-Level Profiling Data)
.scanstats vm 명령도 지원돼요. 이 명령은 각 VM 명령(VM instruction)이 실행된 횟수와 실행 중 흐른 클록 사이클의 백분율을 보여 주는 더 저수준의 프로파일링 보고서를 활성화해요.
sqlite> .scanstats vm
그리고 나서:
sqlite> SELECT count(*) FROM t2 WHERE (d % 5) = 0;
<query results...>
addr cycles nexec opcode p1 p2 p3 p4 p5 comment
---- ------ ------ ------------- ---- ---- ---- ------------- -- -------------
0 0.0% 1 Init 1 18 0 0 Start at 18
1 0.0% 1 Null 0 1 1 0 r[1..1]=NULL
2 0.0% 1 OpenRead 0 2 0 2 0 root=2 iDb=0; t2
3 0.0% 1 ColumnsUsed 0 0 0 2 0
4 0.0% 1 Explain 4 0 0 SCAN t2 0
5 0.0% 1 CursorHint 0 0 0 EQ(REM(c1,5),0) 0
6 0.0% 1 Rewind 0 14 0 0
7 46.86% 150000 Column 0 1 3 0 r[3]= cursor 0 column 1
8 18.94% 150000 Remainder 4 3 2 0 r[2]=r[3]%r[4]
9 5.41% 150000 ReleaseReg 3 1 0 0 release r[3] mask 0
10 12.09% 150000 Ne 5 13 2 80 if r[2]!=r[5] goto 13
11 1.02% 30000 ReleaseReg 2 1 0 0 release r[2] mask 0
12 2.95% 30000 AggStep1 0 0 1 count(0) 0 accum=r[1] step(r[0])
13 12.72% 150000 Next 0 7 0 1
14 0.0% 1 AggFinal 1 0 0 count(0) 0 accum=r[1] N=0
15 0.0% 1 Copy 1 6 0 0 r[6]=r[1]
16 0.0% 1 ResultRow 6 1 0 0 output=r[6]
17 0.01% 1 Halt 0 0 0 0
18 0.0% 1 Transaction 0 0 1 0 1 usesStmtJournal=0
19 0.0% 1 Integer 5 4 0 0 r[4]=5
20 0.0% 1 Integer 0 5 0 0 r[5]=0
21 0.0% 1 Goto 0 1 0 0