Статьи

Как обнаружить медленные запросы с помощью jOOQ

Январь 11, 2019

Он обнаруживает всякий раз, когда генератор кода jOOQ выполняет медленный запрос для обратного инжиниринга метаинформации схемы. Почему?

В нашей тестовой среде для разработки и интеграции у нас нет огромных схем с различными вариантами производительности. Например, у нас нет 5000 синонимов Oracle. Или 10000 процедур с 500 параметрами в каждой. Мы рассмотрим некоторые общие крайние случаи, но не во всех базах данных.

С другой стороны, пользователи склонны принимать статус-кво через некоторое время. Генератор кода работает медленно? Конечно, потому что у нас огромная схема. Это ленивое признание является препятствием для качества нашей продукции. Скорее, наши пользователи сообщают о всевозможных проблемах, с которыми они сталкиваются, поэтому мы хотим их поощрять

И мы сделали

В следующей версии jOOQ 3.8 (и выпусках патчей для 3.5.5, 3.6.5 и 3.7.3) мы добавили в jOOQ-meta симпатичный маленький ExecuteListener , который выглядит примерно так:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
class PerformanceListener
    extends DefaultExecuteListener {
 
    StopWatch watch;
    class SQLPerformanceWarning
        extends Exception {}
 
    @Override
    public void executeStart(ExecuteContext ctx) {
        super.executeStart(ctx);
        watch = new StopWatch();
    }
 
    @Override
    public void executeEnd(ExecuteContext ctx) {
        super.executeEnd(ctx);
        if (watch.split() > 5 * 1000 * 1000 * 1000)
            log.warn(
                "Slow SQL",
                "jOOQ Meta executed a slow query"
              + "\n\n"
              + "Please report this bug here: "
              + "https://github.com/jOOQ/jOOQ/issues/new\n\n"
              + formatted(ctx.query()),
                new SQLPerformanceWarning());
    }
}

Это очень просто. Каждый раз, когда мы начинаем выполнять запрос, запускается «секундомер». Каждый раз, когда мы заканчиваем выполнение, мы проверяем, прошло ли время больше 5 секунд. Если это так, мы регистрируем предупреждение, ссылку на наш трекер ошибок, отформатированную версию запроса SQL и трассировку стека, чтобы помочь найти точное место, где выполнялся медленный оператор.

Давайте запустим это

Причина, по которой мы это сделали, заключается в том, что мы сами убедились, что генератор кода PostgreSQL выполняет медленный запрос для извлечения всех хранимых процедур (и для генерации индексов перегрузки). Полученное сообщение об ошибке:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
[WARNING] Slow SQL                 : jOOQ Meta executed a slow query (slower than 5 seconds)
 
Please report this bug here: https://github.com/jOOQ/jOOQ/issues/new
 
select
  "r1"."routine_schema",
  "r1"."routine_name",
  "r1"."specific_name",
  case when exists (
        select 1 as "one"
        from "information_schema"."parameters"
        where (
          "information_schema"."parameters"."specific_schema" = "r1"."specific_schema"
          and "information_schema"."parameters"."specific_name" = "r1"."specific_name"
          and upper("information_schema"."parameters"."parameter_mode")  'IN'
        )
      ) then 'void'
       else "r1"."data_type"
  end as "data_type",
  "r1"."character_maximum_length",
  "r1"."numeric_precision",
  "r1"."numeric_scale",
  "r1"."type_udt_schema",
  "r1"."type_udt_name",
  case when exists (
        select 1 as "one"
        from "information_schema"."routines" as "r2"
        where (
          "r2"."routine_schema" in (
            'public', 'multi_schema', 'pg_catalog'
          )
          and "r2"."routine_schema" = "r1"."routine_schema"
          and "r2"."routine_name" = "r1"."routine_name"
          and "r2"."specific_name"  "r1"."specific_name"
        )
      ) then (
        select count(*)
        from "information_schema"."routines" as "r2"
        where (
          "r2"."routine_schema" in (
            'public', 'multi_schema', 'pg_catalog'
          )
          and "r2"."routine_schema" = "r1"."routine_schema"
          and "r2"."routine_name" = "r1"."routine_name"
          and "r2"."specific_name" <= "r1"."specific_name"
        )
      ) end as "overload",
  "pg_catalog"."pg_proc"."proisagg"
from "information_schema"."routines" as "r1"
  join "pg_catalog"."pg_namespace"
  on "pg_catalog"."pg_namespace"."nspname" = "r1"."specific_schema"
  join "pg_catalog"."pg_proc"
  on (
    "pg_catalog"."pg_proc"."pronamespace" = "pg_catalog"."pg_namespace".oid
    and (("pg_catalog"."pg_proc"."proname" || '_') || cast("pg_catalog"."pg_proc".oid as varchar)) = "r1"."specific_name"
  )
where (
  "r1"."routine_schema" in (
    'public', 'multi_schema', 'pg_catalog'
  )
  and not("pg_catalog"."pg_proc"."proretset")
)
order by
  "r1"."routine_schema" asc,
  "r1"."routine_name" asc,
  "overload" asc
org.jooq.util.AbstractDatabase$1$SQLPerformanceWarning
        at org.jooq.util.AbstractDatabase$1.executeEnd(AbstractDatabase.java:230)
        at org.jooq.impl.ExecuteListeners.executeEnd(ExecuteListeners.java:163)
        at org.jooq.impl.AbstractResultQuery.execute(AbstractResultQuery.java:269)
        at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:346)
        at org.jooq.impl.AbstractResultQuery.fetch(AbstractResultQuery.java:308)
        at org.jooq.impl.SelectImpl.fetch(SelectImpl.java:2703)
        at org.jooq.util.postgres.PostgresDatabase.getRoutines0(PostgresDatabase.java:707)
        at org.jooq.util.AbstractDatabase.getRoutines(AbstractDatabase.java:1131)
        at org.jooq.util.JavaGenerator.generate(JavaGenerator.java:417)
        at org.jooq.util.JavaGenerator.generate(JavaGenerator.java:314)
        at org.jooq.util.JavaGenerator.generate(JavaGenerator.java:279)
        at org.jooq.util.GenerationTool.run(GenerationTool.java:490)
        at org.jooq.util.GenerationTool.generate(GenerationTool.java:193)
        at org.jooq.util.maven.Plugin.execute(Plugin.java:131)
        ...

Теперь мы можем легко приступить к исправлению запроса.

Вы можете сделать то же самое!

Реализация ExecuteListener была прямой. Вы можете сделать то же самое, очень легко. Просто подключите простой слушатель выполнения к вашей Configuration jOOQ, измеряя скорости выполнения и регистрируя предупреждения после определенного порога.

Удачной отладки!

дальнейшее чтение

По совпадению, очень похожий подход был задокументирован командой инженеров Square — The Query Sniper: https://corner.squareup.com/2016/01/query-sniper.html.

Ссылка: Как обнаружить медленные запросы с помощью jOOQ от нашего партнера по JCG Лукаса Эдера из блога JAVA, SQL и JOOQ .
46
Share: