クエリの発行と処理速度の確認
このドキュメントでは django を利用したコードでクエリを発行し、実際に実行された SQL を確認することでデータベースの特性とどんなコードが効率的になるのかを確認します。
今回は、データベースの INSERT, UPDATE, を行うクエリに関して、その基本的な特性を確認したいと思います。
クエリの発行方法は特定のエンドポイント内で、複数のオブジェクトの作成・更新・取得するような機能を実装し、エンドポイントを叩くことで行いました。
また、発行されたクエリおよび処理速度の確認は、 django-debug-toolbar を使用して行いました。
操作するデータベースのテーブルは、stores_store というテーブルを使用し、テーブル内のカラムは下記の4つのカラムのみを用意しました。
- Store モデル
- id
- name
- created_at
- updated_at
INSERT
初めにデータベースに何かを INSERT するときの処理速度を確認します。
確認した処理速度は以下の4つの時間になります。
- クエリ合計時間
- ユーザーCPU時間
- システムCPU時間
- 経過時間(Elapsed time)
まずはこの4つの時間の意味を確認しておきます。
クエリ合計時間
エンドポイントを叩いてから処理が終わるまでに発行されたクエリを処理するのに使用した時間
ユーザーCPU時間
プログラム内のコードを実行するのに CPU で費やされる時間
システムCPU時間
システムコールなどでプログラムに代わってオペレーティングシステム(OS)のコードを実行するのに CPU で費やされる時間
経過時間
エンドポイントを叩いてから全ての処理が終了するまでの時間
応答の待機時間などはCPU時間に含まれないため、
(クエリ合計時間 + ユーザーCPU時間 + システムCPU時間) != 経過時間
となります
1. 愚直なコードで INSERT を行う
最初の最も単純な例として、下記のコードでオブジェクトを 100 回作成することで、INSERT のクエリを 100 回発行してみました。
# コード1
for _ in range(100):
Store.objects.create(name="jobs")
このときに発行される SQL は下記になり、こちらが 100 回発行されます。
INSERT INTO `stores_store` (`created_at`, `updated_at`, `id`, `name`)
VALUES ('2021-06-07 16:19:16.333428', '2021-06-07 16:19:16.333478', '83158d58fc0c416eb17c2e65de9c6484', 'jobs')
また、そのときに計測した処理速度は次のようになります。
| コード | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|
| 1 | 0.473 | 1.524 | 0.482 | 2.5 |
これだけでは、よく分からなかったため比較のためにコードを次のように変更して、
再度エンドポイントを叩き、処理速度を計測してみました。
# コード番号2
# クエリを発行せずに代わりに、1 を 100 回出力するようにしてみた
for _ in range(100):
print(1)
| コード | クエリの有無 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 1 | 有り | 0.473 | 1.524 | 0.482 | 2.5 |
| 2 | 無し | 0 | 0.013 | 0.003 | 0.019 |
先ほどの INSERT のクエリを発行する処理と比較すると、クエリの発行が無くなることで、
処理速度が劇的に速くなっていることがわかります。
この結果から、クエリを発行する処理がどうして時間がかかるのかを考えると、
当然クエリを処理するのに時間がかかるということも原因の1つなのですが、
実はクエリが発行されるときにデータベースとのやり取りに、CPU のリソースを大量に消費していることが原因なのではないかと読み取れます。
（今回は実際にデータベースとのやり取りにどの程度の CPU リソースが消費されるのかまでは調べられていません）
続いて、クエリの発行数が増えると何か変化があるのかを確認するために、
1のコードのクエリ発行数を 1 万回に増やした次のようなコードで処理速度を計測してみました。
# コード番号3
for _ in range(10000):
Store.objects.create(name="jobs")
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 1 | 100 | 0.473 | 1.524 | 0.482 | 2.5 |
| 3 | 10000 | 43.25 | 136.736 | 35.125 | 217.729 |
クエリの発行数を 100 回から 1 万回の 100 倍に増やしてみましたが、
処理速度も単純に概ね 100 倍程度になり、特に大きな変化はありませんでした。
2. 効率的なコードで INSERT を行う
愚直なコードで INSERT を行うことで、どうやらクエリの処理そのものよりもデータベースとのやり取りを行うための処理に時間がかかっていそうなことがわかりました。
そのため、ここではより効率的なコードで、クエリの発行数を減らすことでデータベースとのやり取りを減らすと処理速度がどのように変化するかを調べたいと思います。
django には、とてもありがたいことにテーブルに複数のレコードを追加する場合でも 1 クエリで処理するための機能があるので、そのコードを使用してみます。
実際に使用するコードと、そのときに発行されるクエリは下記になります。
# コード番号4
obj = []
for _ in range(100):
obj.append(Store(name="jobs"))
# ここで一括でレコードを登録するためのクエリを発行する
Store.objects.bulk_create(obj)
INSERT INTO `stores_store` (`created_at`, `updated_at`, `id`, `name`)
VALUES ('2021-06-07 16:28:36.331845', '2021-06-07 16:28:36.331901', '194b263bb69f4597850b6134bb469af9', 'jobs'),
('2021-06-07 16:28:36.331946', '2021-06-07 16:28:36.331976', '10532093ddd24809ac87e32d790ee533', 'jobs'),
('2021-06-07 16:28:36.332025', '2021-06-07 16:28:36.332048', '1027de1088604162b8320a881ed0e43f', 'jobs'),
・・・ for文のループ回数だけ続いている
また、計測した処理速度は次のようになりました。（比較のためにコード番号1の結果も表示しています）
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 1 | 100 | 0.473 | 1.524 | 0.482 | 2.5 |
| 4 | 1 | 0.004 | 0.227 | 0.026 | 0.265 |
1、4はともにテーブルにレコードを 100 個追加するという同じ処理ですが、クエリの発行数が 1 回で済む4のコード処理速度は 10 倍程度早く処理できることがわかります。
しかし、4はクエリ発行数が 100分の1 になっているので、処理速度が 100 倍になっても良いような気がします。
ここで、各処理にかかった時間を見ると、クエリ合計時間は概ね 100 倍程度になっているのですが、 CPU 時間は 10 倍程度しか高速化していませんでした。
この原因として、次の 2 つのことが可能性として挙げられるのではないかと考えています。
- データベースにアクセスする際に 1 回目は特殊な処理が行われている
- 複数回アクセスする際は、後続のアクセスのコストが低下するように何かしらのキャッシュのようなものが残っているのではないか？
- 発行されたクエリによってデータベースにアクセス際の処理のコストが変わる
- 複雑なクエリほど、CPU による処理コストが増加するのではないか？
続いて、効率なコードでの INSERT もレコードの追加数を 1 万個にして、何か処理速度に変化が起きるかを確認してみます。
コードと処理速度は次のようになります。
# コード番号5
obj = []
for _ in range(10000):
obj.append(Store(name="jobs"))
# ここで一括でレコードを登録するためのクエリを発行する
Store.objects.bulk_create(obj)
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 3 | 10000 | 43.25 | 136.736 | 35.125 | 217.729 |
| 4 | 1 | 0.004 | 0.227 | 0.026 | 0.265 |
| 5 | 1 | 0.366 | 31.486 | 0.932 | 32.585 |
4、5を比較して、なかなか面白い結果が得られたと思います。
クエリの発行数は変わらないものの、4と5では INSERT するレコードの数が 100 倍異なります。
そのため、クエリ合計時間が概ね 100 倍異なるのは妥当だと考えられますが、
ユーザーCPU時間も 100 倍程度異なることは意外でした。
このことから、先ほど 発行されたクエリによってデータベースにアクセス際の処理のコストが変わる のではないかと考えていましたが、
実際に処理コストが変わっている可能性が非常に高いことがわかると思います。
INSERT のまとめ
INSERT のクエリを発行し、その処理速度を計測するという簡単な実験をすることでいくつかデータベースの特徴がわかってきました。
ただし、実際はどうなっているかは調べられていないため、ここでは特徴としてわかったことを仮説としてまとめたいと思います。
-
仮説
- INSERT 処理においては、クエリそのものの処理よりもデータベースにアクセスするための CPU の処理に時間がかかる
- また、それはクエリが複雑であればあるほど顕著になる
- CPU の処理時間に影響を与える度合いは、クエリの複雑さよりもデータベースへのアクセス回数である
-
高速化のために
- INSERT 処理では、複数のクエリをまとめることができるときは必ずまとめる
-
今後の課題
- データベースにアクセス際にどんなことに CPU が使用されているのか
UPDATE
続いて INSERT と同じ要領で UPDATE に関する処理速度を確認します。
UPDATE の処理速度を計測するときのデータベースの状態としては、INSERT の処理速度の計測を行った後のためデータベースには十分な量のレコードが登録されている状態になります。
1. 愚直なコードで UPDATE を行う
それでは、UPDATE でも最も単純な例で、オブジェクトを 100 回更新することで、UPDATE のクエリを 100 回発行してみます。
UPDATE では、INSERT と異なりクエリの処理で最初に必ず UPDATE するためのレコードの情報を取得する必要があるため、1 回 SELECT のクエリが発行されます。
しかし、今回はその SELECT のクエリの影響が小さいことと、そこまで厳密な測定ではないため SELECT のクエリが 1 回発行されていることは無視して考えます。
下記が、計測したコードとその結果になります。
# コード番号6
# store テーブルから 100 レコード取得する
stores = Store.objects.all()[:100]
for store in stores:
# 取得したレコードの name カラムを 'test' に変更
store.name = 'test'
# ここでクエリが発行される
store.save()
# for 文の回数だけ発行される
UPDATE `stores_store`
SET `created_at` = '2021-06-07 16:33:10.373140', `updated_at` = '2021-06-07 16:45:15.085512', `name` = 'test'
WHERE `stores_store`.`id` = '00004d11f0714f998af238ea2e454c30'
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 1 | 100 | 0.473 | 1.524 | 0.482 | 2.5 |
| 6 | 100 | 0.435 | 1.543 | 0.425 | 2.43 |
愚直なコードでの UPDATE の結果は、 同様の INSERT のときと同じような結果になりました。
ここで、UPDATE と INSERT でほぼ同じ傾向の結果になるということは、本質的には UPDATE と INSERT で処理速度に与える影響は無さそうだということがわかります。
また、UPDATE でも INSERT と同様にクエリの発行数を 1 万回に増やして何か変化があるかを確認してみます。
# コード番号7
# store テーブルから 10000 レコード取得する
stores = Store.objects.all()[:10000]
for store in stores:
# 取得したレコードの name カラムを 'test' に変更
store.name = 'test'
# ここでクエリが発行される
store.save()
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 3 | 10000 | 43.25 | 136.736 | 35.125 | 217.729 |
| 6 | 100 | 0.435 | 1.543 | 0.425 | 2.43 |
| 7 | 10000 | 44.319 | 138.628 | 35.275 | 221.258 |
クエリの発行数を増やしても、各処理時間が概ね 100 倍になっただけで特別変わった点は見られませんでした。
また、 INSERT の時と比較してもやはりほぼ同様の結果となることがわかりました。
2. 効率的なコードで UPDATE を行う
続いて UPDATE でも、より効率的なコード（クエリの発行数が少なくて済むコード）で処理時間の計測を行ってみます。
実際に使用するコードと、そのときに発行されるクエリは下記になります。
# コード番号8
stores = Store.objects.all()[:100]
for store in stores:
store.name = 'test'
# ここで一括でクエリを発行する
Store.objects.bulk_update(stores, fields=['name'])
UPDATE `stores_store`
SET `name` = CASE
WHEN (`stores_store`.`id` = '00004d11f0714f998af238ea2e454c30') THEN 'test'
WHEN (`stores_store`.`id` = '000080be137e483fabc82bcd81ad7747') THEN 'test'
WHEN (`stores_store`.`id` = '0000869bb3744f13b591248ad595fe76') THEN 'test'
WHEN (`stores_store`.`id` = '00026a79864e4bb4a8eab517e0ab8f30') THEN 'test'
WHEN (`stores_store`.`id` = '0002a3d775af41698c4853ee2be28e9a') THEN 'test'
WHEN (`stores_store`.`id` = '0005ea4f2ff74583822c802bd48d5fcc') THEN 'test'
WHEN (`stores_store`.`id` = '0006b950117641a381de191958bb07a9') THEN 'test'
・
・ # for文の回数だけ WHEN で id を指定
・
ELSE NULL
END
WHERE `stores_store`.`id`
IN ('00004d11f0714f998af238ea2e454c30',
'000080be137e483fabc82bcd81ad7747',
'0000869bb3744f13b591248ad595fe76',
'00026a79864e4bb4a8eab517e0ab8f30',
'0002a3d775af41698c4853ee2be28e9a',
'0005ea4f2ff74583822c802bd48d5fcc',
'0006b950117641a381de191958bb07a9',
・・・・・
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 4 | 1 | 0.004 | 0.227 | 0.026 | 0.265 |
| 6 | 100 | 0.435 | 1.543 | 0.425 | 2.43 |
| 8 | 1 | 0.009 | 0.452 | 0.136 | 0.595 |
この測定でも UPDATE は INSERT とほぼ同様の結果となり、 UPDATE でもクエリ発行数を減らすことが処理速度の向上には重要なことがわかります。
念のため、この測定でもコードを次のように変えて、更新するレコード数を 1 万に増やしてみます。
# コード番号9
stores = Store.objects.all()[:10000]
for store in stores:
store.name = 'test'
# ここで一括でクエリを発行する
Store.objects.bulk_update(stores, fields=['name'])
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 5 | 1 | 0.366 | 31.486 | 0.932 | 32.585 |
| 7 | 10000 | 44.319 | 138.628 | 35.275 | 221.258 |
| 8 | 1 | 0.009 | 0.452 | 0.136 | 0.595 |
| 9 | 1 | 3.537 | 210.236 | 4.989 | 217.509 |
8、9のコードを比較すると、更新するレコードの数を 100 倍すると、各処理時間が 400 ~ 500 倍になっていることがわかります。
これは今までの傾向と何かが違う気がします。
愚直なコードの7と比較しても、処理時間にほとんど差がありません。
また、同じようなことを INSERT で行った５のコードと比較しても、各処理にかかる時間が 5 ~ 10 倍増えていることがわかります。
今までの測定結果から、 INSERT と UPDATE は本質的な処理のコストは同じだということが考えられます。
しかし、ここでは INSER と UPDATE の処理時間に大きな差があります。
5、9のコードでの大きな違いを見てみると、発行されるクエリの SQL 文の長さに大きな違いがありました。
そこで、この処理時間の違いは次の仮説が考えられると思います。
- クエリの複雑さを表す指標として、SQL 文の長さがその要因の1つになり得るのではないか
- しかし、単に SQL 文の長さに比例して複雑になっているとは言えない
また、9のコードが 1 クエリしか発行していないのに 10000 クエリ発行している7のコードと処理時間がほぼ同じことから、 INSERT の結果から考えていた CPU の処理時間に影響を与える度合いは、クエリの複雑さよりもデータベースへのアクセス回数である という仮説はどうやら間違っている可能性が高いことがわかりました。
3. 大量のレコード更新をより効率的に行うための UPDATE
では、大量のレコードを UPDATE する場合は、 処理コスト的に INSERT よりも不利になってしまうのでしょうか。
先ほどの仮説を元に考えると発行するクエリの SQL 文をより短いものにすることができれば UPDATE の処理コストを低下させることができそうです。
これまた django にはより短い SQL 文でクエリを発行することができるコードがあります。
そのコードと、そのときに発行されるクエリは下記になります。
# コード番号10
# 更新対象のレコードの id を取得
stores = Store.objects.all()[:10000]
ids = stores.values_list('id', flat=True)
# ここで一括でクエリを発行
Store.objects.filter(id__in=list(ids)).update(name='test')
UPDATE `stores_store`
SET `name` = 'test'
WHERE `stores_store`.`id`
IN ('00004d11f0714f998af238ea2e454c30',
'000080be137e483fabc82bcd81ad7747',
'0000869bb3744f13b591248ad595fe76',
'00026a79864e4bb4a8eab517e0ab8f30',
'0002a3d775af41698c4853ee2be28e9a',
'0005ea4f2ff74583822c802bd48d5fcc',
# 取得したレコード数だけ id が続く
)
| コード | クエリ発行数 | クエリ合計時間[s] | ユーザーCPU時間[s] | システムCPU時間[s] | 経過時間[s] |
|---|---|---|---|---|---|
| 5 | 1 | 0.366 | 31.486 | 0.932 | 32.585 |
| 9 | 1 | 3.537 | 210.236 | 4.989 | 217.509 |
| 10 | 1 | 0.128 | 56.561 | 0.962 | 57.651 |
結果を見ていきます。
コード10で発行される SQL 文は、コード9と比較して CASE と WHEN で記述された部分が無くなっているため、SQL 文の長さが非常に短くなっていることがわかります。
また、処理速度も各処理にかかる時間が大幅に減少し、コード9と比較して数倍の速度で処理を終えることができるようになったことがわかります。
これは、コード5の INSERT と同様の傾向に戻ったと言えると思います。
したがって、発行される SQL 文の長さは処理速度に大きな影響を与える1つの要因として考えることができると思います。
UPDATE のまとめ
-
仮説
- UPDATE 処理にかかるコストは本質的には INSERT 処理と同じ
- クエリの複雑さは SQL 文の長さが要因の1つとなる
-
高速化のために
- クエリの発行数はできるだけ少なくする
- 発行されるクエリの SQL はできるだけ短くする
-
今後の課題
- クエリの発行数が同じでも処理速度に大きな影響が出る原因の詳細がわかっていないこと
INSERT と UPDATE からわかったことのまとめ直し
-
仮説
- INSERT 処理においては、クエリそのものの処理よりもデータベースにアクセスするための CPU の処理に時間がかかる
- また、それはクエリが複雑であればあるほど顕著になる
- UPDATE 処理にかかるコストは本質的には INSERT 処理と同じ
- クエリの複雑さは SQL 文の長さが要因の1つとなる
-
高速化のために
- クエリの発行数はできるだけ少なくする
- 発行されるクエリの SQL はできるだけ短くする
-
今後の課題
- クエリの発行数が同じでも処理速度に大きな影響が出る原因の詳細がわかっていないこと
- データベースにアクセス際にどんなことに CPU が使用されているのか
終わりに
普段何気なく発行しているクエリですが、簡単なクエリを発行してその処理速度を計測するだけでも、多くの情報が分かった気がします。
今回のような知見を積み重ねて、同じ機能を持ったコードでもより高速に処理できるコードを書いていきたいと思いました。
Discussion