Postgres EXPLAIN ANALYZE Общее время, превышающее сумму частей - PullRequest
Новая
       11

Postgres EXPLAIN ANALYZE Общее время, превышающее сумму частей

0 голосов
/ 02 июня 2019

Я пытаюсь выявить некоторые узкие места в производительности в моих запросах Postgres и набрал EXPLAIN ANALYZE для запроса, чтобы получить некоторое представление.Результат анализа запроса приведен ниже: 

    Nested Loop  (cost=162.35..5361.39 rows=4385 width=33) (actual time=5.663..315.153 rows=2 loops=1)
  ->  Seq Scan on "User" p=u  (cost=0.00..1.02 rows=1 width=8) (actual time=0.009..0.011 rows=1 loops=1)
        Filter: ("ID" = 1)
        Rows Removed by Filter: 1
  ->  Nested Loop  (cost=162.35..5316.51 rows=4385 width=33) (actual time=5.646..315.130 rows=2 loops=1)
        ->  Nested Loop  (cost=161.93..1854.59 rows=6574 width=33) (actual time=5.567..106.350 rows=44342 loops=1)
              ->  Seq Scan on "Op" o  (cost=0.00..1.34 rows=1 width=8) (actual time=0.007..0.011 rows=1 loops=1)
                    Filter: ("Name" = 'write'::text)
                    Rows Removed by Filter: 26
              ->  Bitmap Heap Scan on "Account" a  (cost=161.93..1768.73 rows=8453 width=33) (actual time=5.551..45.435 rows=44342 loops=1)
                    Recheck Cond: ("OId" = o."ID")
                    Filter: ("UId" = 1)
                    Heap Blocks: exact=1480
                    ->  Bitmap Index Scan on "IX_Account_op_ID"  (cost=0.00..159.82 rows=8453 width=0) (actual time=5.138..5.139 rows=44342 loops=1)
                          Index Cond: ("OId" = o."ID")
        ->  Index Scan using "PK_Resource_ID" on "Resources" r  (cost=0.42..0.53 rows=1 width=8) (actual time=0.003..0.003 rows=0 loops=44342)
              Index Cond: ("ID" = a."ResourceId")
              Filter: ("Role" = ANY ('{r1,r2,r3,r4,r5}'::text[]))
              Rows Removed by Filter: 1
Planning Time: 0.777 ms
Execution Time: 315.220 ms

Я не проводил много анализа запросов с помощью pg объяснения, поэтому я все еще пытаюсь обернуть голову вокруг всего, что он говорит мне здесь.Одна вещь, которую я вижу, вызывает у меня некоторое замешательство, что я вижу внешнее выполнение: 

Nested Loop  (cost=162.35..5361.39 rows=4385 width=33) (actual time=5.663..315.153 rows=2 loops=1)

говорит, что фактическое время было 5,663 ... 315 - хорошо, это имеет смысл, так как общее время выполнения было315. Затем, чуть ниже:

Вложенный цикл (стоимость = 162.35..5316.51 строк = 4385 ширина = 33) (фактическое время = 5.646..315.130 строк = 2 цикла = 1)

Ok!Это говорит мне о том, что основная часть времени выполнения будет в этом разделе.Под этим я вижу: 

    ->  Nested Loop  (cost=161.93..1854.59 rows=6574 width=33) (actual time=5.567..106.350 rows=44342 loops=1)
          ->  Seq Scan on "Op" o  (cost=0.00..1.34 rows=1 width=8) (actual time=0.007..0.011 rows=1 loops=1)
                Filter: ("Name" = 'write'::text)
                Rows Removed by Filter: 26
          ->  Bitmap Heap Scan on "Account" a  (cost=161.93..1768.73 rows=8453 width=33) (actual time=5.551..45.435 rows=44342 loops=1)
                Recheck Cond: ("OId" = o."ID")
                Filter: ("UId" = 1)
                Heap Blocks: exact=1480

Ха - так это говорит о том, что существует вложенный цикл, который занял 106.35 ms, который зациклился один раз, и содержимое этого цикла было сканированием sq, которое заняло .011ms и растровое сканирование кучи, которое заняло 45.435ms.

Все циклы имеют 1 цикл, но в обоих случаях мне кажется, что общее выполнение этих циклов было выше, чем сумма содержимого циклов.В случае внутреннего цикла для выполнения потребовалось 106ms, но, если я сложу содержимое этого цикла, похоже, что для этого потребовалось только 45.446ms (.011ms + 45.435ms).В случае внешнего цикла это заняло 315.13ms, но опять же, если я сложу содержимое, похоже, что оно должно было быть 106.353ms (106.35ms + .003ms).

Я смотрю на это и предполагаю, что loop = 1 означает, что он выполнял только то, что было внутри этого цикла, один раз ... хотя общее время предполагает, что было выполнено более одного выполнения.Я не уверен, где я неверно истолковал это.Может ли кто-нибудь пролить свет на это для меня?Любой совет здесь будет оценен, большое спасибо!

1 Ответ

1 голос
/ 03 июня 2019

ANALYZE не показывает, сколько времени занимает выполнение задач в SELECT tasks FROM [..].Здесь pg_sleep(1) занимает 20000 мс (20x1сек), но вы видите его только в Nested Loop разделе 

explain (analyze, verbose)
select *, pg_sleep(1)
  from generate_series(1,5) AS w
  cross join generate_series(current_date,current_date+3,interval '1 day') AS v;

QUERY PLAN
Nested Loop  (cost=0.02..22510.02 rows=1000000 width=16) (actual time=1001.082..20021.134 rows=20 loops=1)
  Output: w.w, v.v, pg_sleep('1'::double precision)
  ->  Function Scan on pg_catalog.generate_series w  (cost=0.00..10.00 rows=1000 width=4) (actual time=0.006..0.008 rows=5 loops=1)
        Output: w.w
        Function Call: generate_series(1, 5)
  ->  Function Scan on pg_catalog.generate_series v  (cost=0.02..10.02 rows=1000 width=8) (actual time=0.005..0.010 rows=4 loops=5)
        Output: v.v
        Function Call: generate_series((('now'::cstring)::date)::timestamp with time zone, ((('now'::cstring)::date + 3))::timestamp with time zone, '1 day'::interval)
Planning time: 0.093 ms
Execution time: 20021.178 ms

. Это не показывает, сколько времени занимает JOIN наборов данных.Здесь получение данных занимает около 1000 мс, но СОЕДИНЕНИЕ этих наборов занимает в 4 раза больше, потому что вы видите увеличение во времени в разделе Nested Loop примерно на столько, и это единственное, что нужно было сделать, и он не был указан в подробном плане. 

explain (analyze, verbose)
select *
  from generate_series(1,50000) AS w
  cross join generate_series(current_date,current_date+30,interval '1 day') AS v;

QUERY PLAN
Nested Loop  (cost=0.02..20010.02 rows=1000000 width=12) (actual time=3.237..3128.123 rows=1550000 loops=1)
  Output: w.w, v.v
  ->  Function Scan on pg_catalog.generate_series w  (cost=0.00..10.00 rows=1000 width=4) (actual time=3.210..35.472 rows=50000 loops=1)
        Output: w.w
        Function Call: generate_series(1, 50000)
  ->  Function Scan on pg_catalog.generate_series v  (cost=0.02..10.02 rows=1000 width=8) (actual time=0.001..0.021 rows=31 loops=50000)
        Output: v.v
        Function Call: generate_series((('now'::cstring)::date)::timestamp with time zone, ((('now'::cstring)::date + 30))::timestamp with time zone, '1 day'::interval)
Planning time: 0.046 ms
Execution time: 4103.113 ms
...