DBIx::TracerでN+1クエリを検知できるようにした

- DBIx::TracerでN+1クエリを検知できるようにした
- YAPC::Tokyo 2019 前夜祭 LTソン presented by 吉祥寺.pm

Transcript

1. DBIx::TracerͰN+1ΫΤϦΛݕ ஌Ͱ͖ΔΑ͏ʹͨ͠ɻ by @return520
2. ΋͘͡ - ؆୯ࣗݾ঺հ - N+1ͱ͸ - ࣮࿩ - ࣮૷ - ݁Ռ - ·ͱΊ
3. ؆୯ࣗݾ঺հ
4. ࣗݾ঺հ - େੲʹڝϓϩ΍ͬͯͨɻ - ύιίϯߕࢠԂͱ͔ɻ - U-20ϓϩίϯͰ৆ͱ͔΋Βͬͨɻ - ͜͜͠͹Β͘͸ɺޒ൓ాͰPerlॻ͍ͯ·͢ɻ - ͋ͱAWSͱ͔jsͱ͔΋ɻ @return520
5. ࣗݾ঺հ - YAPCॳࢀՃͰ͢ɻ - PerlͰN+1Λ؆୯ʹݕ஌͢Δ࿩Λ͠·͢ɻ @return520
6. N+1ͱ͸
7. N+1ͱ͸ SQLͷΫΤϦ͕ͨ͘͞Μൃߦ͞Εͯɺ RDBMS͕ͭΒ͍ࢥ͍Λ͢Δ͜ͱɻ ʻͻ͌ʂ ʻͻ͌ʂ
8. ͭΒ͍ͷ͸஌ͬͯΔ
9. Ͱ΋ੜΈग़ͯ͠͠·͏
10. ੜΈग़͞ΕΔN+1 - ॳ৺ऀ͸஌ΒͣʹੜΈग़ͯ͠͠·͏ɻ - ஌ͬͯͯ΋ؾ͔ͮͣੜΈग़ͯ͠͠·͏ɻ - ͦ΋ͦ΋ͳΜ͔͋ͬͨɻ
11. ࣮࿩... <ॿ͚ͯʂ
12. ࣮࿩̍ - ৽ػೳϦϦʔεͨ͠ΒN+1ͰΞϓϦ͕ܹॏʹͳͬͨ - ϦϦʔεͨ͠ॠؒɺRDS͕ߴෛՙ - ͙͢ʹrevert - Α͘ݟͨΒN+1Ͱselect͕80ճ͞ΕͯΔ
13. ࣮࿩̎ - ͦ΋ͦ΋ͳΜ͔͋Δ - ಈ͍ͯΔ͚Ͳ์ஔ͞ΕͯΔAPI - ਺೥લʹ࡞ΒΕͯ࡞ͬͨਓ͕͍ͳ͍ - ίʔυ΋࢓༷΋ෳࡶͰख͕ग़ͮ͠Β͍
14. ݟ͚ͭͯ͸मਖ਼ͯ͠Δ
15. ݟ͚ͭͯ͸मਖ਼͍ͯ͠Δ - slow_query_logͰॏ͍ͷ࣏͢ɻ - apiͷ଎౓ܭଌͯ͠ɺ஗͍apiΛվળ͢Δɻ - ॲཧ·Δ·Δॻ͖௚͢ɻ
16. ݟ͚ͭͯ͸मਖ਼ͯ͠Δ͚Ͳ ະવʹ๷͍͗ͨ
17. ΋ͬͱָʹϘτϧωοΫΛ ݟ͚͍ͭͨ
18. ݕ஌Ͱ͖ΔΑ͏ʹ͠Α͏ʂ
19. ࠓճͷΞʔΩςΫνϟ - Perl5 - Amon2 - ORM Aniki + α - AWS (EC2 + Aurora)
20. ݱঢ়੔ཧ - ORMΛ࢖༻͍ͯ͠ΔͷͰɺqueryͷ͹Β͖ͭ͸ଟ෼ແ͍ɻ - SELECT͕େจࣈͩͬͨΓখจࣈͩͬͨΓ͸͠ͳ͍͸ͣɻ - ΄΅΄΅ಉ͡query͕࣮ߦ͞ΕΔ͸ͣɻ => data bind͞Ε͍ͯΔ෦෼Λ͍͍ײ͡ʹڞ௨ԽͰ͖Ε͹ಉҰqueryͷ࣮ߦΛ ݕ஌Ͱ͖ͦ͏ɻ
21. ΞΠσΟΞ - API͕ୟ͔ΕΔʢAmon2ͷBEFORE_DISPATCHʣ - SQLͷ࣮ߦΛϑοΫ͢Δɻ - ྲྀΕ͍ͯΔSQLΛਖ਼نԽ͢Δ - ಉҰqueryΛcount͢Δ - count͕Ұఆ਺Λ௒͑ͨΒɺlogʹు͖ग़͢ɻ - ॲཧऴྃʢAmon2ͷAFTER_DISPATCHʣ
22. SQLͷ࣮ߦΛϑοΫ͢Δ
23. SQLͷ࣮ߦΛϑοΫ͢Δɻ - DBIx::Tracer͕͋Δ͡Όͳ͍͔ʂʂ - https://metacpan.org/pod/DBIx::Tracer
24. SQLͷ࣮ߦΛϑοΫ͢Δɻ __PACKAGE__->add_trigger( BEFORE_DISPATCH => sub { my ($c) = @_; $c->{__dbix_tracer} = DBIx::Tracer->new(sub { my %args = @_; my $sql = $args{sql}; # ࣮ߦ͞ΕΔSQL }); } ) 

25. ྲྀΕ͍ͯΔSQLΛਖ਼نԽ͢Δ
26. ϑοΫͨ͠SQL͸͜Μͳײͩͬͨ͡ SELECT `id`, `fuga_id`, `read_fg`, `created_at`, `updated_at` FROM `hoge` WHERE (`read_fg` = ?) AND (`fuga_id` = ?) վߦফ͚ͩ͢Ͱେৎ෉ͦ͏ɻ ྲྀΕ͍ͯΔSQLΛਖ਼نԽ͢Δ
27. sub normaliz_sql{ my ($sql) = shift; $sql =~ s/\r?\n?//g; return $sql; } ྲྀΕ͍ͯΔSQLΛਖ਼نԽ͢Δ
28. ಉҰqueryΛcount͢Δ
29. ಉҰqueryΛcount͢Δ
 my %query_count; sub count_query { my ($sql) = shift; $query_count{$sql}++; }
30. count͕Ұఆ਺Λ௒͑ͨΒɺlogʹు͖ग़͢ɻ

31. count͕Ұఆ਺Λ௒͑ͨΒɺlogʹు͖ग़͢ɻ sub check_n1_query {
 my ($class, $query_count) = @_;
 
 foreach my $sql (keys %$query_count) {
 my $count = $query_count{$sql};
 warn “warning n+1 query count:[$count] SQL:[$sql]” if ($query_count >= 5); } }
32. ؆୯ʹͰ͖·ͨ͠ɻ
33. ͋Γ͕ͱ͏ʂʂ DBIx::Tracerʂʂ
34. ͜ͷ͋ͱ໓஡ۤ஡ ϦϑΝΫλͨ͠
35. ϦϑΝΫλ݁Ռ લʢඵʣ ޙʢඵʣ ճ਺ લʢ࣌ؒʣ ޙʢ࣌ؒʣ ࠩʢ࣌ؒʣ 1.3 0.7 2504868 904.54 487.06 417.48 0.8 0.1 597798 132.84 16.61 116.23 0.8 0.4 1406491 312.55 156.28 156.27 0.45 0.2 5547284 693.41 308.18 385.23 0.2 0.09 1605089 89.17 40.13 49.04 0.2 0.1 8369158 464.95 232.48 232.47 etc...
36. ϦϑΝΫλ݁Ռ Ұ೔ͷॲཧ͕࣌ؒ 1356.72࣌ؒʢ56.53೔ʣݮͬͨɻ ʢଞʹ΋΍ͬͯΔͷͰɺ΋ͬͱ΋ͬͱݮͬͯΔ
37. ϦϑΝΫλ݁Ռ Ұ೔ͷॲཧ͕࣌ؒ 1356.72࣌ؒʢ56.53೔ʣݮͬͨɻ ʢଞʹ΋΍ͬͯΔͷͰɺ΋ͬͱ΋ͬͱݮͬͯΔ ϦϑΝΫλָ͍͠ʂʂʂ
38. ·ͱΊ
39. ·ͱΊ - DBIx::TracerΛ࢖͑͹؆୯ʹ࡞ΕΔɻ - ϦϑΝΫλָ͕͘͠ͳΔɻ
40. ͓·͚ - caller ࢖͏ͱݺͼग़͠ݩ΋logʹग़ͤΔɻ - ϦϑΝΫλָ͕͘͠ͳΔɻ
41. ͓ΘΓ