DBクエリの削減効果
実装前と実装後のクエリの変化を見たかったので、github.com/walf443/go-sql-tracerを利用して簡単にチェックしてみた。
以下のようなひどいクエリを投げたときに
query {
visitor {
id
name
diaries {
id
name
user {
id
name
diaries {
id
name
user {
diaries {
name
}
}
}
}
}
}
}
DataLoaderの仕組みを使う前は次のログが流れ、大量のSQLが発行され、かつ同じデータなのに何度も取得してしまっている。
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id,name FROM user JOIN user_session
app_1 | ON user.id = user_session.user_id
app_1 | WHERE user_session.token = ? && user_session.expires_at > ?
app_1 | LIMIT 1; args = ["abTQRlcvAk8LIYZDk0YX9Kd5bZUGZHEXsAjvy4d84405nNLJsWKt5IoaZt2PpJev5oEwOjWZLda2bFPyc76VmJXXZZ47S1Tid8yXwy3OVpOmNptauv0sikNY@lRZcf8M", time.Time{wall:0xbf60130bdb2204dc, ext:220321424901, loc:(*time.Location)(0xae5a00)}]; err = "driver: skip fast-path; continue as if unimplemented" (22.3µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id,name FROM user JOIN user_session
app_1 | ON user.id = user_session.user_id
app_1 | WHERE user_session.token = ? && user_session.expires_at > ?
app_1 | LIMIT 1; args = ["abTQRlcvAk8LIYZDk0YX9Kd5bZUGZHEXsAjvy4d84405nNLJsWKt5IoaZt2PpJev5oEwOjWZLda2bFPyc76VmJXXZZ47S1Tid8yXwy3OVpOmNptauv0sikNY@lRZcf8M", time.Time{wall:0xbf60130bdb2204dc, ext:220321424901, loc:(*time.Location)(0xae5a00)}] (788.5µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (20.5µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (16.5µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (601.1µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (17.6µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (17µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (2.3747ms)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (33.2µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (19.5µs)
app_1 | 2019/10/11 01:02:39 Open 0xc4202a20c0 (4.9426ms)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (16.6µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (567.7µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a20c0 (16.3µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (22µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (2.3667ms)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (88.9µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (17.4µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (450.6µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (1.1051ms)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (18µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a20c0 (15.9µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (17.9µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (18.2µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (342.9µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (652.4µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a20c0 (15µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (16.2µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (21.2µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (392.2µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a20c0 (16.1µs)
app_1 | 2019/10/11 01:02:39 Open 0xc4201563c0 (5.1434ms)
app_1 | 2019/10/11 01:02:39 Query 0xc4201563c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (19.1µs)
app_1 | 2019/10/11 01:02:39 Open 0xc420156540 (5.6406ms)
app_1 | 2019/10/11 01:02:39 Query 0xc420156540: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (19.8µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4201563c0: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (608.5µs)
app_1 | 2019/10/11 01:02:39 Close 0xc4201563c0 (124µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (21.8µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a2300: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (536.7µs)
app_1 | 2019/10/11 01:02:39 Query 0xc420156540: SELECT id, name FROM user
app_1 | WHERE id = ? LIMIT 1; args = [26351446802825216] (1.5906ms)
app_1 | 2019/10/11 01:02:39 Close 0xc420156540 (87.8µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a2300 (15.2µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (17.8µs)
app_1 | 2019/10/11 01:02:39 Query 0xc4202a20c0: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id = ?
app_1 | ORDER BY created_at DESC; args = [26351446802825216] (545.2µs)
app_1 | 2019/10/11 01:02:39 ResetSession 0xc4202a20c0 (17.1µs)
一方同一のGraphQLクエリでも、DataLoaderの仕組みを利用すると、WHERE INでまとめて取得し、かつメモリにキャッシュしてくれているので何度も同じDBクエリを発行しなくなった。まあ今回は引数が一つしかないのでWHERE INの効果は少ないが、キャッシュによって同一のデータを取得しなくても済むのは大きい。
app_1 | 2019/10/11 14:05:44 Query 0xc4202c4000: SELECT id,name FROM user JOIN user_session
app_1 | ON user.id = user_session.user_id
app_1 | WHERE user_session.token = ? && user_session.expires_at > ?
app_1 | LIMIT 1; args = ["rOCbpziPUOEoZznWVe2C64J5Jz@TlC_iNG0KkrnHyfSarXz12y0_aPNpHOuBf1UMOhp5N4J1eBAi0lDfC14xJ@YAwaiTVZa@m_doAKium9ZlpL3aLhzRcYQOy8YexKUk", time.Time{wall:0xbf6040ee23e6db60, ext:31234792601, loc:(*time.Location)(0xaf4a00)}] (1.2528ms)
app_1 | 2019/10/11 14:05:44 ResetSession 0xc4202c4000 (45.5µs)
app_1 | 2019/10/11 14:05:44 Query 0xc4202c4000: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id IN (?); args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (17µs)
app_1 | 2019/10/11 14:05:44 Query 0xc4202c4000: SELECT id, user_id, name FROM diary
app_1 | WHERE user_id IN (?); args = [26351446802825216] (584.4µs)
app_1 | 2019/10/11 14:05:44 ResetSession 0xc4202c4000 (21µs)
app_1 | 2019/10/11 14:05:44 Query 0xc4202c4000: SELECT id,name FROM user
app_1 | WHERE id IN (?); args = [26351446802825216]; err = "driver: skip fast-path; continue as if unimplemented" (20µs)
app_1 | 2019/10/11 14:05:44 Query 0xc4202c4000: SELECT id,name FROM user
app_1 | WHERE id IN (?); args = [26351446802825216] (517.9µs)
app_1 | 2019/10/11 14:05:44 ResetSession 0xc4202c4000 (600.2µs)