前回で実行計画も見れるようになったので実際にベンチマークをとっていく。
PostgreSQL上でのベンチマークをとる準備その2 - gos-k’s blog
前提としてこれは私がDBを知らないから試しているのであって、まともに勉強している人にとって新しい情報は何も出てこないと思う。
以前作ったレコード数100万だと少なそうな気がしたので1億に増やす。
中断もあり出来上がりまで2日くらいかかった。
runとexplを再定義する。
(ql:quickload '(:cl-dbi :sxql))
(defvar *connection*
(dbi:connect :postgres
:database-name "test"
:username "myuser"
:password "1234"))
(defun run (sxql &key silent)
(multiple-value-bind (sql binds)
(sxql:yield sxql)
(let ((query (dbi:execute (dbi:prepare *connection*
sql)
binds)))
(unless silent
(format t "~{~S~%~}" (dbi:fetch-all query))))))
(defun expl (sxql &key silent analyze verbose)
(multiple-value-bind (sql binds)
(sxql:explain sxql
:analyze analyze
:verbose verbose)
(let ((query (dbi:execute (dbi:prepare *connection*
sql)
binds)))
(unless silent
(format t "~{~A~%~}" (mapcar #'second
(dbi:fetch-all query)))))))
単純にレコード数を数える時間の計測。
(time (run (sxql:select ((:count :*)) (sxql:from :bench1))))
(:|count| 100000000)
Evaluation took:
28.944 seconds of real time
0.076228 seconds of total run time (0.068817 user, 0.007411 system)
0.26% CPU
130 lambdas converted
75,019,658,522 processor cycles
9,039,856 bytes consed
28.944秒。結構時間かかるが短すぎると計測出来ないのでまあとりあえずこんなもんで。レコード数1000万でも良かったかもしれないが。
もう一度実行する。
(time (run (sxql:select ((:count :*)) (sxql:from :bench1))))
(:|count| 100000000)
Evaluation took:
2.516 seconds of real time
0.008230 seconds of total run time (0.007765 user, 0.000465 system)
0.32% CPU
34 lambdas converted
6,527,313,242 processor cycles
851,184 bytes consed
今度は2.516秒。一桁速いので何らかキャッシュが効いてそうだが、それなりなので同一SQLはLUTを引くような速さではなさそう。
その後何度か実行するが大きくは変わらず。
インデックスの有無
現状のインデックスを確認。
(run (sxql:select (:tablename :indexname)
(sxql:from :pg_indexes)
(sxql:where (:not (:like :tablename "pg_%")))))
PostgreSQL側のインデックスしかないので何も表示されない。
プライマリキーにはデフォルトでインデックスつくような話があった気がするが、そういえばテーブルの定義にプライマリつけてなかった。
インデックスなしで計測
uuidをソートして（そんなことしても普通実用的な意味は無いが）値が大きいものを取り出す。
(time (run (sxql:select (:*) (sxql:from :bench1)
(sxql:order-by (:desc :uuid))
(sxql:limit 1))))
(:|uuid| "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B" :|int_data| 35 :|real_data| 81.5925)
Evaluation took:
11.179 seconds of real time
0.001657 seconds of total run time (0.001657 user, 0.000000 system)
0.02% CPU
28,971,618,296 processor cycles
59,888 bytes consed
取得に11.179秒。
uuidを指定して取得。
(time (run (sxql:select (:*) (sxql:from :bench1)
(sxql:where (:= :uuid "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B")))))
(:|uuid| "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B" :|int_data| 35 :|real_data| 81.5925)
Evaluation took:
2.380 seconds of real time
0.001368 seconds of total run time (0.001191 user, 0.000177 system)
0.04% CPU
6,171,428,638 processor cycles
32,784 bytes consed
取得に2.380秒。
インデックスありで計測
とりあえずbench1のuuidに関するインデックスを作る。
(time (run (sxql:create-index :bench1_uuid_index :on '(:bench1 :uuid))))
Evaluation took:
320.967 seconds of real time
0.009390 seconds of total run time (0.000000 user, 0.009390 system)
0.00% CPU
831,940,213,012 processor cycles
67,120 bytes consed
再び1つ取り出す。
(time (run (sxql:select (:*) (sxql:from :bench1)
(sxql:order-by (:desc :uuid))
(sxql:limit 1))))
(:|uuid| "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B" :|int_data| 35 :|real_data| 81.5925)
Evaluation took:
0.000 seconds of real time
0.003648 seconds of total run time (0.003148 user, 0.000500 system)
100.00% CPU
5,614,760 processor cycles
65,520 bytes consed
計測できないほど速くなった。
uuid指定も同様に。
(time (run (sxql:select (:*) (sxql:from :bench1)
(sxql:where (:= :uuid "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B")))))
(:|uuid| "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B" :|int_data| 35 :|real_data| 81.5925)
Evaluation took:
0.012 seconds of real time
0.000978 seconds of total run time (0.000853 user, 0.000125 system)
8.33% CPU
24,829,884 processor cycles
0 bytes consed
こちらは時間計測できて実行時間が100分の1以下となった。
(:|uuid| "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B" :|int_data| 35 :|real_data| 81.5925)
Evaluation took:
0.000 seconds of real time
0.000803 seconds of total run time (0.000698 user, 0.000105 system)
100.00% CPU
5,650,996 processor cycles
32,544 bytes consed
2回目実行したら計測不能。
計測不能なので実行計画を見る。
(expl (sxql:select (:*) (sxql:from :bench1)
(sxql:where (:= :uuid "FFFFFFF4-3400-4E53-B670-F09C03D7CB9B"))))
Index Scan using bench1_uuid_index on bench1 (cost=0.57..8.59 rows=1 width=45)
Index Cond: ((uuid)::text = 'FFFFFFF4-3400-4E53-B670-F09C03D7CB9B'::text)
ないものを探す。
(time (run (sxql:select (:*)
(sxql:from :bench1)
(sxql:where (:= :uuid "dummy")))))
Evaluation took:
0.004 seconds of real time
0.000635 seconds of total run time (0.000526 user, 0.000109 system)
25.00% CPU
3,656,096 processor cycles
0 bytes consed
0.004秒。
索引のない整数について50以下を取り出す。
(time (run (sxql:select ((:count :*))
(sxql:from :bench1)
(sxql:where (:< :int_data 50))
(sxql:group-by :int_data)
(sxql:order-by (:desc :int_data)))))
Evaluation took:
30.532 seconds of real time
0.028304 seconds of total run time (0.023632 user, 0.004672 system)
0.09% CPU
156 lambdas converted
79,134,651,138 processor cycles
9,826,656 bytes consed
30.532秒。
2回目の実行。
Evaluation took:
4.743 seconds of real time
0.007597 seconds of total run time (0.007597 user, 0.000000 system)
0.17% CPU
34 lambdas converted
12,290,504,776 processor cycles
851,200 bytes consed
大分速くなって4.743秒。
整数に索引をつける。
(time (run (sxql:create-index :bench1_int_data_index :on '(:bench1 :int_data))))
Evaluation took:
62.028 seconds of real time
0.004582 seconds of total run time (0.004582 user, 0.000000 system)
0.01% CPU
34 lambdas converted
160,772,178,188 processor cycles
726,208 bytes consed
62.028秒。
索引ありで整数の50以下を取り出す。
(time (run (sxql:select ((:count :*))
(sxql:from :bench1)
(sxql:where (:< :int_data 50))
(sxql:group-by :int_data)
(sxql:order-by (:desc :int_data)))))
Evaluation took:
4.316 seconds of real time
0.005106 seconds of total run time (0.000328 user, 0.004778 system)
0.12% CPU
0 processor cycles
End of buffer consed
4.316秒。あまり変わらない。同一のクエリに対して索引相当のキャッシュが作られる？
実数の50.0以下を取り出す。
(time (run (sxql:select ((:count :*) :real_data)
(sxql:from :bench1)
(sxql:where (:< :real_data 50.0))
(sxql:group-by :real_data)
(sxql:order-by (:asc :real_data)))))
Evaluation took:
11.135 seconds of real time
0.730950 seconds of total run time (0.633282 user, 0.097668 system)
6.56% CPU
28,859,121,622 processor cycles
446,585,280 bytes consed
11.135秒。2回目。
Evaluation took:
11.651 seconds of real time
0.738516 seconds of total run time (0.701032 user, 0.037484 system)
[ Run times consist of 0.109 seconds GC time, and 0.630 seconds non-GC time. ]
6.34% CPU
30,196,880,508 processor cycles
1 page fault
436,348,768 bytes consed
11.651秒。整数の一回目が遅いのが何か特殊？
索引を実数につける。
(time (run (sxql:create-index :bench1_real_data_index :on '(:bench1 :real_data)))
Evaluation took:
88.633 seconds of real time
0.017629 seconds of total run time (0.016032 user, 0.001597 system)
0.02% CPU
229,724,215,970 processor cycles
1,568,528 bytes consed
索引ありで実数の50.0以下を取り出す。
(time (run (sxql:select ((:count :*) :real_data)
(sxql:from :bench1)
(sxql:where (:< :real_data 50.0))
(sxql:group-by :real_data)
(sxql:order-by (:asc :real_data)))))
Evaluation took:
12.112 seconds of real time
0.632849 seconds of total run time (0.613674 user, 0.019175 system)
5.23% CPU
31,400,792,736 processor cycles
435,509,344 bytes consed
12.112秒。索引の効果がない。
selectを実行するとそのキャッシュが出来る仕組みなんだろうか？
とりあえず何も分からないこということが分かった。
