I have a question on the execution time of a query and the fluctuations I'm
seeing. I enabled auto_trace to capture some actual executions of a query by
an app. Below are 2 executions of it. The top one took 1.697 milliseconds.
The 2nd one took 31.241 milliseconds. Note the query has hints in it and the
top one did not obey the hint to use the pk index on table product. That table
is very small so full scanning it isn't really a problem. When I look at the
steps in the plan below I do not believe the difference in runtime is due to
plan differences.
Here are my observations for the top query/plan:
- The query found 318 rows when scanning the entry_guid_mod_idx index on table
entry. It did 336 or 337 shared block hits for that step and it took 619
milliseconds for this step.
- I believe it nested looped to the full scan of table product 318 times.
That step took 812 milliseconds (time including prior step). At that point the
query did a total of 841 shared block hits. I believe it found 318 rows that
matched.
- The LockRows step- this is coming from the SELECT FOR UPDATE SKIP LOCKED.
I believe this step shows it returned 0 rows. Runtime was 1.696 seconds. This
implies all 318 rows that matched the query were all locked.
Observations for the bottom query/plan:
- The query found 291 rows when scanning the entry_guid_mod_idx index on table
entry. It did 313 or 315 shared block sits for that step and it took 977
milliseconds.
- I believe it nested looped to the index scan pkproduct 291 times. That step
took 1.491 seconds (time including prior step). Ad that point the query did a
total of 1365 shared block hits. I believe it found 291 rows that matched.
- The LockRows step- Again, I believe this is coming from the SELECT FOR
UPDATE SKIP LOCKED. Like the top query this also shows it returned 0 rows
which implies to me all 291 rows were locked. But here we can see the runtime
was 31.239 milliseconds.
So my question- assuming my understanding above is correct both plans show it
taking minimal time to get to the LockRows step. The top query skipped more
rows than the bottom query but the bottom query took significantly more time at
this LockRows step. Why would that be the case?
Thanks in advance.
Steve
2023-11-29 18:12:45
UTC:10.210.202.108(50098):alertu@pgbatchshared01aq:[15251]:LOG: duration:
1.697 ms plan:
Query Text: /*+ NestLoop(t1 t2) IndexScan(t2 pkproduct) */ SELECT
T1.ENTRY_GUID FROM bchalertdemo.ENTRY T1,bchalertdemo.PRODUCT T2 WHERE
T1.NEXT_RUN_DATE<$1 AND T1.STATUS_CODE=1 AND T2.ACTIVE_STATUS != 'F' AND
(END_DATE IS NULL OR ($2 < END_DATE)) AND (($3 NOT BETWEEN SUSPEND_DATE AND
RESUME_DATE) OR SUSPEND_DATE IS NULL OR RESUME_DATE IS NULL) AND
T1.PRODUCT_CODE = T2.PRODUCT_CODE AND T1.LAST_RUN_DATE<$4 AND T2.PRODUCT_VALUE
IN ($5) AND MOD(ABS(HASHTEXT(T1.ENTRY_GUID)),150) = $6 ORDER BY T1.PRIORITY,
T1.ENTRY_FREQUENCY_CODE, T1.NEXT_RUN_DATE FOR UPDATE SKIP LOCKED LIMIT 1
Limit (cost=0.42..4.63 rows=1 width=64) (actual time=1.695..1.696 rows=0
loops=1)
Buffers: shared hit=841
-> LockRows (cost=0.42..1393.48 rows=331 width=64) (actual
time=1.695..1.695 rows=0 loops=1)
Buffers: shared hit=841
-> Nested Loop (cost=0.42..1390.17 rows=331 width=64) (actual
time=0.032..0.812 rows=318 loops=1)
Join Filter: (t1.product_code = t2.product_code)
Buffers: shared hit=337
-> Index Scan using entry_guid_mod_idx on entry t1
(cost=0.42..1384.18 rows=331 width=63) (actual time=0.016..0.619 rows=318
loops=1)
Index Cond: ((mod(abs(hashtext((entry_guid)::text)),
150) = 141) AND (next_run_date < '2023-11-29 12:12:38.535'::timestamp without
time zone) AND (last_run_date < '2023-11-29 12:12:38.535'::timestamp without
time zone)
AND (status_code = '1'::numeric))
Filter: (((end_date IS NULL) OR ('2023-11-29
12:12:38.535'::timestamp without time zone < end_date)) AND (('2023-11-29
12:12:38.535'::timestamp without time zone < suspend_date) OR ('2023-11-29
12:12:38.535'::timestamp
without time zone > resume_date) OR
(suspend_date IS NULL) OR (resume_date IS NULL)))
Buffers: shared hit=336
-> Materialize (cost=0.00..1.02 rows=1 width=20) (actual
time=0.000..0.000 rows=1 loops=318)
Buffers: shared hit=1
-> Seq Scan on product t2 (cost=0.00..1.01 rows=1
width=20) (actual time=0.013..0.013 rows=1 loops=1)
Filter: ((active_status <> 'F'::bpchar) AND
((product_value)::text = 'bchalert-poc'::text))
Buffers: shared hit=1
2023-11-29 18:12:45
UTC:10.210.202.108(50006):alertu@pgbatchshared01aq:[15226]:LOG: duration:
31.241 ms plan:
Query Text: /*+ NestLoop(t1 t2) IndexScan(t2 pkproduct) */ SELECT
T1.ENTRY_GUID FROM bchalertdemo.ENTRY T1,bchalertdemo.PRODUCT T2 WHERE
T1.NEXT_RUN_DATE<$1 AND T1.STATUS_CODE=1 AND T2.ACTIVE_STATUS != 'F' AND
(END_DATE IS NULL OR ($2 < END_DATE)) AND (($3 NOT BETWEEN SUSPEND_DATE AND
RESUME_DATE) OR SUSPEND_DATE IS NULL OR RESUME_DATE IS NULL) AND
T1.PRODUCT_CODE = T2.PRODUCT_CODE AND T1.LAST_RUN_DATE<$4 AND T2.PRODUCT_VALUE
IN ($5) AND MOD(ABS(HASHTEXT(T1.ENTRY_GUID)),150) = $6 ORDER BY T1.PRIORITY,
T1.ENTRY_FREQUENCY_CODE, T1.NEXT_RUN_DATE FOR UPDATE SKIP LOCKED LIMIT 1
Limit (cost=0.55..5.50 rows=1 width=64) (actual time=31.238..31.239
rows=0 loops=1)
Buffers: shared hit=1365
-> LockRows (cost=0.55..366.92 rows=74 width=64) (actual
time=31.237..31.238 rows=0 loops=1)
Buffers: shared hit=1365
-> Nested Loop (cost=0.55..366.18 rows=74 width=64) (actual
time=0.044..1.491 rows=291 loops=1)
Buffers: shared hit=315
-> Index Scan using entry_guid_mod_idx on entry t1
(cost=0.42..363.72 rows=74 width=63) (actual time=0.035..0.977 rows=291 loops=1)
Index Cond: ((mod(abs(hashtext((entry_guid)::text)),
150) = $6) AND (next_run_date < $1) AND (last_run_date < $4) AND (status_code =
'1'::numeric))
Filter: (((end_date IS NULL) OR ($2 < end_date)) AND
(($3 < suspend_date) OR ($3 > resume_date) OR (suspend_date IS NULL) OR
(resume_date IS NULL)))
Buffers: shared hit=313
-> Memoize (cost=0.14..0.32 rows=1 width=20) (actual
time=0.001..0.001 rows=1 loops=291)
Cache Key: t1.product_code
Cache Mode: logical
Hits: 290 Misses: 1 Evictions: 0 Overflows: 0
Memory Usage: 1kB
Buffers: shared hit=2
-> Index Scan using pkproduct on product t2
(cost=0.12..0.31 rows=1 width=20) (actual time=0.005..0.006 rows=1 loops=1)
Index Cond: (product_code = t1.product_code)
Filter: ((active_status <> 'F'::bpchar) AND
((product_value)::text = ($5)::text))
Buffers: shared hit=2
This e-mail is for the sole use of the intended recipient and contains
information that may be privileged and/or confidential. If you are not an
intended recipient, please notify the sender by return e-mail and delete this
e-mail and any attachments. Certain required legal entity disclosures can be
accessed on our website:
https://www.thomsonreuters.com/en/resources/disclosures.html
