pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedQuery is slow when run for first time; subsequent execution is fast
13+ messages / 7 participants
[nested] [flat]
* Query is slow when run for first time; subsequent execution is fast
@ 2018-01-10 11:59 Nandakumar M <m.nanda92@gmail.com>
0 siblings, 1 reply; 13+ messages in thread
From: Nandakumar M @ 2018-01-10 11:59 UTC (permalink / raw)
To: pgsql-performance
Hello,
This is my first question in postgres mailing list. If there are any
mistakes, please don't mind.
I am using PostgreSQL 9.4.4 on a Mac machine executing queries on postgres
server through the psql client.
servicedesk=# select version();
version
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
PostgreSQL 9.4.4 on x86_64-apple-darwin, compiled by
i686-apple-darwin11-llvm-gcc-4.2 (GCC) 4.2.1 (Based on Apple Inc. build
5658) (LLVM build 2336.11.00), 64-bit
(1 row)
Repeatedly, I came across instances where any query when run for the first
time takes longer time to execute (nearly 2 second sometimes), but
subsequent execution of the same query is very fast (less than 20
milliseconds).
The tables involved in the query also have very less number of rows (less
than 50).
On running explain (analyze, buffers) got the following results.
-- start --
servicedesk=#
servicedesk=# explain (analyze, buffers, verbose) SELECT COUNT(*) FROM
ChangeDetails LEFT JOIN SDOrganization AaaOrg ON
ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=13.25..13.26 rows=1 width=160) (actual time=0.018..0.018
rows=1 loops=1)
Output: count(*)
Buffers: shared hit=1
-> Seq Scan on public.changedetails (cost=0.00..12.60 rows=260
width=160) (actual time=0.007..0.008 rows=2 loops=1)
Output: changedetails.changeid, changedetails.initiatorid,
changedetails.technicianid, changedetails.stageid,
changedetails.priorityid, changedetails.categoryid,
changedetails.subcategoryid, changedetails.itemid,
changedetails.appr_statusid, changedetails.changetypeid,
changedetails.urgencyid, changedetails.title, changedetails.description,
changedetails.createdtime, changedetails.scheduledstarttime,
changedetails.scheduledendtime, changedetails.completedtime,
changedetails.notespresent, changedetails.siteid, changedetails.groupid,
changedetails.templateid, changedetails.wfid, changedetails.wfstageid,
changedetails.wfstatusid, changedetails.isemergency,
changedetails.isretrospective, changedetails.reasonforchangeid,
changedetails.closurecodeid, changedetails.changemanagerid,
changedetails.riskid, changedetails.impactid, changedetails.slaid,
changedetails.isoverdue
Buffers: shared hit=1
Planning time: 468.239 ms
Execution time: 0.104 ms
(8 rows)
servicedesk=#
servicedesk=# explain (analyze, buffers, verbose) SELECT COUNT(*) FROM
ChangeDetails LEFT JOIN SDOrganization AaaOrg ON
ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=13.25..13.26 rows=1 width=160) (actual time=0.009..0.009
rows=1 loops=1)
Output: count(*)
Buffers: shared hit=1
-> Seq Scan on public.changedetails (cost=0.00..12.60 rows=260
width=160) (actual time=0.005..0.005 rows=2 loops=1)
Output: changedetails.changeid, changedetails.initiatorid,
changedetails.technicianid, changedetails.stageid,
changedetails.priorityid, changedetails.categoryid,
changedetails.subcategoryid, changedetails.itemid,
changedetails.appr_statusid, changedetails.changetypeid,
changedetails.urgencyid, changedetails.title, changedetails.description,
changedetails.createdtime, changedetails.scheduledstarttime,
changedetails.scheduledendtime, changedetails.completedtime,
changedetails.notespresent, changedetails.siteid, changedetails.groupid,
changedetails.templateid, changedetails.wfid, changedetails.wfstageid,
changedetails.wfstatusid, changedetails.isemergency,
changedetails.isretrospective, changedetails.reasonforchangeid,
changedetails.closurecodeid, changedetails.changemanagerid,
changedetails.riskid, changedetails.impactid, changedetails.slaid,
changedetails.isoverdue
Buffers: shared hit=1
Planning time: 1.058 ms
Execution time: 0.066 ms
(8 rows)
-- end --
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-10 19:34 Jeff Janes <jeff.janes@gmail.com>
parent: Nandakumar M <m.nanda92@gmail.com>
0 siblings, 1 reply; 13+ messages in thread
From: Jeff Janes @ 2018-01-10 19:34 UTC (permalink / raw)
To: Nandakumar M <m.nanda92@gmail.com>; pgsql-performance
On Wed, Jan 10, 2018 at 3:59 AM, Nandakumar M <m.nanda92@gmail.com> wrote:
>
> I am not using prepared statements. Postgres documentation and previous
> questions in the pgsql-performance mailing list mention that the query plan
> is cached only when prepared statements are used.
>
> https://www.postgresql.org/message-id/15600.1346885470%40sss.pgh.pa.us
>
> In the above thread Tom Lane mentions that the plan is never cached for
> raw queries. Yet, this is exactly what seems to be happening in my case. Am
> I missing something?
>
The query plan itself is not cached, but all the metadata about the (large
number) of tables used in the query is cached. Apparently reading/parsing
that data is the slow step, not coming up with the actual plan.
> Please let me know how I can make sure the query execution for the first
time is fast too.
Don't keep closing and reopening connections. Use a connection pooler
(pgbouncer, pgpool, whatever pooler is built into your
language/library/driver, etc.) if necessary to accomplish this.
Cheers,
Jeff
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-12 08:03 Nandakumar M <m.nanda92@gmail.com>
parent: Jeff Janes <jeff.janes@gmail.com>
0 siblings, 3 replies; 13+ messages in thread
From: Nandakumar M @ 2018-01-12 08:03 UTC (permalink / raw)
To: Jeff Janes <jeff.janes@gmail.com>; pgsql-performance
Hello Jeff,
Thanks for the insights.
>Don't keep closing and reopening connections.
Even if I close a connection and open a new one and execute the same query,
the planning time is considerably less than the first time. Only when I
restart the Postgres server then I face high planning time again.
>The query plan itself is not cached, but all the metadata about the (large
number) of tables used in the query is cached. Apparently reading/parsing
that data is the slow step, not coming up with the actual plan.
I enabled logging for parser, planner etc in postgresql.conf and re run the
queries. Following is the logs - I am not sure exactly how this should be
read, but the major difference in elapsed time seems to be in PLANNER
STATISTICS section.
-- start --
1. First run
LOG: PARSER STATISTICS
DETAIL: ! system usage stats:
! 0.000482 elapsed 0.000356 user 0.000127 system sec
! [0.004921 user 0.004824 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/102 [0/1076] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
! 0/0 [8/11] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: statement: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN
SDOrganization AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: PARSE ANALYSIS STATISTICS
DETAIL: ! system usage stats:
! 0.030012 elapsed 0.006251 user 0.006894 system sec
! [0.011270 user 0.011777 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/1036 [0/2126] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
! 154/5 [163/16] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: REWRITER STATISTICS
DETAIL: ! system usage stats:
! 0.000058 elapsed 0.000052 user 0.000006 system sec
! [0.011350 user 0.011793 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/6 [0/2132] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
! 0/0 [163/16] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: PLANNER STATISTICS
DETAIL: ! system usage stats:
! 0.326018 elapsed 0.013452 user 0.009604 system sec
! [0.024821 user 0.021400 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/531 [0/2663] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
! 51/71 [214/87] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.000047 elapsed 0.000026 user 0.000019 system sec
! [0.024961 user 0.021461 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/13 [0/2709] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
! 0/0 [214/87] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: duration: 357.192 ms
2. Second run
LOG: PARSER STATISTICS
DETAIL: ! system usage stats:
! 0.000169 elapsed 0.000161 user 0.000018 system sec
! [0.025308 user 0.021656 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/4 [0/2716] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
! 0/0 [215/87] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: statement: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN
SDOrganization AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: PARSE ANALYSIS STATISTICS
DETAIL: ! system usage stats:
! 0.002665 elapsed 0.001974 user 0.000196 system sec
! [0.027325 user 0.021866 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/17 [0/2734] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
! 0/56 [215/144] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: REWRITER STATISTICS
DETAIL: ! system usage stats:
! 0.000068 elapsed 0.000068 user 0.000000 system sec
! [0.027425 user 0.021876 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
! 0/0 [215/144] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: PLANNER STATISTICS
DETAIL: ! system usage stats:
! 0.001025 elapsed 0.000917 user 0.000105 system sec
! [0.028363 user 0.021986 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
! 0/1 [215/145] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.000016 elapsed 0.000016 user 0.000000 system sec
! [0.028449 user 0.021993 sys total]
! 0/0 [0/1] filesystem blocks in/out
! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
! 0/0 [215/145] voluntary/involuntary context switches
STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
ApprovalStatusDefinition ON
ChangeDetails.APPR_STATUSID=ApprovalStatusDefinition.STATUSID LEFT JOIN
CategoryDefinition ON
ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
Change_StageDefinition ON
ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID LEFT JOIN
Change_StatusDefinition ON
ChangeDetails.WFSTATUSID=Change_StatusDefinition.WFSTATUSID LEFT JOIN
AaaUser ChangeManager ON
ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID LEFT
JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
LEFT JOIN ChangeResolution ON
ChangeDetails.CHANGEID=ChangeResolution.CHANGEID LEFT JOIN ChangeTemplate
ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID LEFT JOIN
ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
LEFT JOIN Change_ClosureCode ON
ChangeToClosureCode.ID=Change_ClosureCode.ID LEFT JOIN ChangeTypeDefinition
ON ChangeDetails.CHANGETYPEID=ChangeTypeDefinition.CHANGETYPEID LEFT JOIN
ChangeWF_Definition ON ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN
ImpactDefinition ON ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT
JOIN ItemDefinition ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
PriorityDefinition ON
ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID LEFT JOIN
QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID LEFT JOIN
RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID LEFT JOIN
StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID LEFT JOIN
SubCategoryDefinition ON
ChangeDetails.SUBCATEGORYID=SubCategoryDefinition.SUBCATEGORYID LEFT JOIN
UrgencyDefinition ON ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID
LEFT JOIN SDUser ON ChangeDetails.INITIATORID=SDUser.USERID;
LOG: duration: 4.277 ms
-- end --
a. If someone could interpret what exactly the PLANNER STATISTICS section
means (to identify the exact bottleneck) it would be great!
b. Sometimes, first execution of a query takes nearly 2 seconds of planning
time. This seems to be too high even for the first run of the query. Will
some configuration change help speed up the planning time? Also, is there
any way to pre warm the caches so that the meta data that is required for
the query planning is available in cache before hand?
Thanks and regards,
Nanda
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-12 10:04 Pavel Stehule <pavel.stehule@gmail.com>
parent: Nandakumar M <m.nanda92@gmail.com>
2 siblings, 1 reply; 13+ messages in thread
From: Pavel Stehule @ 2018-01-12 10:04 UTC (permalink / raw)
To: Nandakumar M <m.nanda92@gmail.com>; +Cc: Jeff Janes <jeff.janes@gmail.com>; pgsql-performance
2018-01-12 9:03 GMT+01:00 Nandakumar M <m.nanda92@gmail.com>:
> Hello Jeff,
>
> Thanks for the insights.
>
> >Don't keep closing and reopening connections.
>
> Even if I close a connection and open a new one and execute the same
> query, the planning time is considerably less than the first time. Only
> when I restart the Postgres server then I face high planning time again.
>
> >The query plan itself is not cached, but all the metadata about the
> (large number) of tables used in the query is cached. Apparently
> reading/parsing that data is the slow step, not coming up with the actual
> plan.
>
> I enabled logging for parser, planner etc in postgresql.conf and re run
> the queries. Following is the logs - I am not sure exactly how this should
> be read, but the major difference in elapsed time seems to be in PLANNER
> STATISTICS section.
>
> -- start --
>
> 1. First run
>
> LOG: PARSER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000482 elapsed 0.000356 user 0.000127 system sec
> ! [0.004921 user 0.004824 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/102 [0/1076] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
> ! 0/0 [8/11] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: statement: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN
> SDOrganization AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: PARSE ANALYSIS STATISTICS
> DETAIL: ! system usage stats:
> ! 0.030012 elapsed 0.006251 user 0.006894 system sec
> ! [0.011270 user 0.011777 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/1036 [0/2126] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
> ! 154/5 [163/16] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: REWRITER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000058 elapsed 0.000052 user 0.000006 system sec
> ! [0.011350 user 0.011793 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/6 [0/2132] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
> ! 0/0 [163/16] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: PLANNER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.326018 elapsed 0.013452 user 0.009604 system sec
> ! [0.024821 user 0.021400 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/531 [0/2663] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
> ! 51/71 [214/87] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: EXECUTOR STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000047 elapsed 0.000026 user 0.000019 system sec
> ! [0.024961 user 0.021461 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/13 [0/2709] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [3/5] messages rcvd/sent
> ! 0/0 [214/87] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: duration: 357.192 ms
>
>
> 2. Second run
>
>
> LOG: PARSER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000169 elapsed 0.000161 user 0.000018 system sec
> ! [0.025308 user 0.021656 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/4 [0/2716] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
> ! 0/0 [215/87] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: statement: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN
> SDOrganization AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: PARSE ANALYSIS STATISTICS
> DETAIL: ! system usage stats:
> ! 0.002665 elapsed 0.001974 user 0.000196 system sec
> ! [0.027325 user 0.021866 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/17 [0/2734] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
> ! 0/56 [215/144] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: REWRITER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000068 elapsed 0.000068 user 0.000000 system sec
> ! [0.027425 user 0.021876 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
> ! 0/0 [215/144] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: PLANNER STATISTICS
> DETAIL: ! system usage stats:
> ! 0.001025 elapsed 0.000917 user 0.000105 system sec
> ! [0.028363 user 0.021986 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
> ! 0/1 [215/145] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: EXECUTOR STATISTICS
> DETAIL: ! system usage stats:
> ! 0.000016 elapsed 0.000016 user 0.000000 system sec
> ! [0.028449 user 0.021993 sys total]
> ! 0/0 [0/1] filesystem blocks in/out
> ! 0/0 [0/2734] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [4/21] messages rcvd/sent
> ! 0/0 [215/145] voluntary/involuntary context switches
> STATEMENT: SELECT COUNT(*) FROM ChangeDetails LEFT JOIN SDOrganization
> AaaOrg ON ChangeDetails.SITEID=AaaOrg.ORG_ID LEFT JOIN
> ApprovalStatusDefinition ON ChangeDetails.APPR_STATUSID=
> ApprovalStatusDefinition.STATUSID LEFT JOIN CategoryDefinition ON
> ChangeDetails.CATEGORYID=CategoryDefinition.CATEGORYID LEFT JOIN
> Change_Fields ON ChangeDetails.CHANGEID=Change_Fields.CHANGEID LEFT JOIN
> Change_StageDefinition ON ChangeDetails.WFSTAGEID=Change_StageDefinition.WFSTAGEID
> LEFT JOIN Change_StatusDefinition ON ChangeDetails.WFSTATUSID=
> Change_StatusDefinition.WFSTATUSID LEFT JOIN AaaUser ChangeManager ON
> ChangeDetails.CHANGEMANAGERID=ChangeManager.USER_ID LEFT JOIN AaaUser
> ChangeOriginator ON ChangeDetails.INITIATORID=ChangeOriginator.USER_ID
> LEFT JOIN AaaUser ChangeOwner ON ChangeDetails.TECHNICIANID=ChangeOwner.USER_ID
> LEFT JOIN ChangeResolution ON ChangeDetails.CHANGEID=ChangeResolution.CHANGEID
> LEFT JOIN ChangeTemplate ON ChangeDetails.TEMPLATEID=ChangeTemplate.TEMPLATEID
> LEFT JOIN ChangeToClosureCode ON ChangeDetails.CHANGEID=ChangeToClosureCode.CHANGEID
> LEFT JOIN Change_ClosureCode ON ChangeToClosureCode.ID=Change_ClosureCode.ID
> LEFT JOIN ChangeTypeDefinition ON ChangeDetails.CHANGETYPEID=
> ChangeTypeDefinition.CHANGETYPEID LEFT JOIN ChangeWF_Definition ON
> ChangeDetails.WFID=ChangeWF_Definition.ID LEFT JOIN ImpactDefinition ON
> ChangeDetails.IMPACTID=ImpactDefinition.IMPACTID LEFT JOIN ItemDefinition
> ON ChangeDetails.ITEMID=ItemDefinition.ITEMID LEFT JOIN
> PriorityDefinition ON ChangeDetails.PRIORITYID=PriorityDefinition.PRIORITYID
> LEFT JOIN QueueDefinition ON ChangeDetails.GROUPID=QueueDefinition.QUEUEID
> LEFT JOIN RiskDefinition ON ChangeDetails.RISKID=RiskDefinition.RISKID
> LEFT JOIN StageDefinition ON ChangeDetails.STAGEID=StageDefinition.STAGEID
> LEFT JOIN SubCategoryDefinition ON ChangeDetails.SUBCATEGORYID=
> SubCategoryDefinition.SUBCATEGORYID LEFT JOIN UrgencyDefinition ON
> ChangeDetails.URGENCYID=UrgencyDefinition.URGENCYID LEFT JOIN SDUser ON
> ChangeDetails.INITIATORID=SDUser.USERID;
> LOG: duration: 4.277 ms
>
>
> -- end --
>
> a. If someone could interpret what exactly the PLANNER STATISTICS section
> means (to identify the exact bottleneck) it would be great!
>
> b. Sometimes, first execution of a query takes nearly 2 seconds of
> planning time. This seems to be too high even for the first run of the
> query. Will some configuration change help speed up the planning time?
> Also, is there any way to pre warm the caches so that the meta data that is
> required for the query planning is available in cache before hand?
>
maybe some your indexes and some system tables are bloated. Try you run
VACUUM FULL ANALYZE
Regards
Pavel
> Thanks and regards,
> Nanda
>
^ permalink raw reply [nested|flat] 13+ messages in thread
* Fwd: Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-16 11:46 Nandakumar M <m.nanda92@gmail.com>
parent: Pavel Stehule <pavel.stehule@gmail.com>
0 siblings, 0 replies; 13+ messages in thread
From: Nandakumar M @ 2018-01-16 11:46 UTC (permalink / raw)
To: pgsql-performance
Missed to have mailing list in to address.. forwarding now.
---------- Forwarded message ----------
From: "Nandakumar M" <m.nanda92@gmail.com>
Date: 15 Jan 2018 12:16
Subject: Re: Query is slow when run for first time; subsequent execution is
fast
To: "Pavel Stehule" <pavel.stehule@gmail.com>
Cc:
Hi,
On Fri, Jan 12, 2018 at 3:34 PM, Pavel Stehule <pavel.stehule@gmail.com>
wrote:
>
> >> maybe some your indexes and some system tables are bloated. Try you run
> VACUUM FULL ANALYZE
>
Tried this suggestion. Planning time gets reduced slightly but it is still
way higher on the first run compared to subsequent runs of the same query.
Regards,
Nanda
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-16 12:20 Thomas Kellerer <spam_eater@gmx.net>
parent: Nandakumar M <m.nanda92@gmail.com>
2 siblings, 0 replies; 13+ messages in thread
From: Thomas Kellerer @ 2018-01-16 12:20 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
Nandakumar M schrieb am 12.01.2018 um 09:03:
> Even if I close a connection and open a new one and execute the same
> query, the planning time is considerably less than the first time.
> Only when I restart the Postgres server then I face high planning
> time again.
Yes, because the data is cached by Postgres ("shared_buffers") and the filesystem.
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-17 05:18 Jeff Janes <jeff.janes@gmail.com>
parent: Nandakumar M <m.nanda92@gmail.com>
2 siblings, 2 replies; 13+ messages in thread
From: Jeff Janes @ 2018-01-17 05:18 UTC (permalink / raw)
To: Nandakumar M <m.nanda92@gmail.com>; +Cc: pgsql-performance
On Fri, Jan 12, 2018 at 12:03 AM, Nandakumar M <m.nanda92@gmail.com> wrote:
> Hello Jeff,
>
> Thanks for the insights.
>
> >Don't keep closing and reopening connections.
>
> Even if I close a connection and open a new one and execute the same
> query, the planning time is considerably less than the first time. Only
> when I restart the Postgres server then I face high planning time again.
>
Oh. I've not seen that before. But then again I don't often restart my
server and then immediately run very large queries with a stringent time
deadline.
You can try pg_prewarm, on pg_statistic table and its index. But I'd
probably just put an entry in my db startup script to run this query
immediately after startng the server, and let the query warm the cache
itself.
Why do you restart your database often enough for this to be an issue?
Cheers,
Jeff
^ permalink raw reply [nested|flat] 13+ messages in thread
* RE: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-17 07:25 POUSSEL, Guillaume <guillaume.poussel@sogeti.com>
parent: Jeff Janes <jeff.janes@gmail.com>
1 sibling, 1 reply; 13+ messages in thread
From: POUSSEL, Guillaume @ 2018-01-17 07:25 UTC (permalink / raw)
To: Jeff Janes <jeff.janes@gmail.com>; Nandakumar M <m.nanda92@gmail.com>; +Cc: pgsql-performance
Hello,
FWIW, I do have the same issue.
Unfortunately our application is running on a standard laptop/desktop computers, not dedicated servers.
Restarting the computer leads to a restart of the database server, which slow down all queries for several minutes.
Are you on Windows or Linux? I’m on Windows and wondering if the issue is the same on Linux?
BR,
Guillaume
De : Jeff Janes [mailto:jeff.janes@gmail.com]
Envoyé : mercredi 17 janvier 2018 06:18
À : Nandakumar M
Cc : pgsql-performa.
Objet : Re: Query is slow when run for first time; subsequent execution is fast
On Fri, Jan 12, 2018 at 12:03 AM, Nandakumar M <m.nanda92@gmail.com <mailto:m.nanda92@gmail.com> > wrote:
Hello Jeff,
Thanks for the insights.
>Don't keep closing and reopening connections.
Even if I close a connection and open a new one and execute the same query, the planning time is considerably less than the first time. Only when I restart the Postgres server then I face high planning time again.
Oh. I've not seen that before. But then again I don't often restart my server and then immediately run very large queries with a stringent time deadline.
You can try pg_prewarm, on pg_statistic table and its index. But I'd probably just put an entry in my db startup script to run this query immediately after startng the server, and let the query warm the cache itself.
Why do you restart your database often enough for this to be an issue?
Cheers,
Jeff
This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
Attachments:
[application/pkcs7-signature] smime.p7s (5.9K, ../../DB5PR0201MB15758B7FA662A6B04509AE359CE90@DB5PR0201MB1575.eurprd02.prod.outlook.com/3-smime.p7s)
download
^ permalink raw reply [nested|flat] 13+ messages in thread
* RE: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-17 10:09 Nandakumar M <m.nanda92@gmail.com>
parent: POUSSEL, Guillaume <guillaume.poussel@sogeti.com>
0 siblings, 0 replies; 13+ messages in thread
From: Nandakumar M @ 2018-01-17 10:09 UTC (permalink / raw)
To: pgsql-performance; guillaume.poussel@sogeti.com; +Cc: Jeff Janes <jeff.janes@gmail.com>
Hi,
On 17 Jan 2018 12:55, "POUSSEL, Guillaume" <guillaume.poussel@sogeti.com>
wrote:
Are you on Windows or Linux? I’m on Windows and wondering if the issue is
the same on Linux?
I have experienced this on Mac and Linux machines.
You can try pg_prewarm, on pg_statistic table and its index. But I'd
probably just put an entry in my db startup script to run this query
immediately after startng the server, and let the query warm the cache
itself.
I will try this suggestion and get back on the thread. Is pg_statistic the
only table to be pre cached? Pls let me know if any other table/index needs
to be pre warmed.
Btw, I don't running a "select * from pg_statistic" will fill the shared
buffer. Only 256 kb of data will be cached during sequential scans. I will
try pg_prewarm
Why do you restart your database often
Postgres is bundled with our application and deployed by our client.
Starting / stopping the server is not under my control.
Regards,
Nanda
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-18 01:55 Michael Paquier <michael.paquier@gmail.com>
parent: Jeff Janes <jeff.janes@gmail.com>
1 sibling, 1 reply; 13+ messages in thread
From: Michael Paquier @ 2018-01-18 01:55 UTC (permalink / raw)
To: Jeff Janes <jeff.janes@gmail.com>; +Cc: Nandakumar M <m.nanda92@gmail.com>; pgsql-performance
On Tue, Jan 16, 2018 at 09:18:25PM -0800, Jeff Janes wrote:
> Oh. I've not seen that before. But then again I don't often restart my
> server and then immediately run very large queries with a stringent time
> deadline.
>
> You can try pg_prewarm, on pg_statistic table and its index. But I'd
> probably just put an entry in my db startup script to run this query
> immediately after startng the server, and let the query warm the cache
> itself.
>
> Why do you restart your database often enough for this to be an issue?
Another thing that you could use here is pg_buffercache which offers a
way to look at the Postgres shared buffer contents in real-time:
https://www.postgresql.org/docs/current/static/pgbuffercache.html
As Jeff says, pg_prewarm is a good tool for such cases to avoid any kind
of warmup period when a server starts..
--
Michael
Attachments:
[application/pgp-signature] signature.asc (832B, ../../20180118015532.GE29962@paquier.xyz/2-signature.asc)
download
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-01-26 07:43 Nandakumar M <m.nanda92@gmail.com>
parent: Michael Paquier <michael.paquier@gmail.com>
0 siblings, 0 replies; 13+ messages in thread
From: Nandakumar M @ 2018-01-26 07:43 UTC (permalink / raw)
To: Michael Paquier <michael.paquier@gmail.com>; Jeff Janes <jeff.janes@gmail.com>; pgsql-performance
Hi,
I tried pg_prewarm as suggested by Jeff Janes and it works - thanks a lot
Jeff. Now the query planning is fast on the first execution.
Here is the list of tables that needed to be pre warmed (or you could just
pre warm all the 'pg_%' tables. :-) ).
select pg_prewarm('pg_statistic');
select pg_prewarm('pg_trigger_tgrelid_tgname_index');
select pg_prewarm('pg_trigger');
select pg_prewarm('pg_statistic_relid_att_inh_index');
select pg_prewarm('pg_index_indrelid_index');
select pg_prewarm('pg_index_indexrelid_index');
select pg_prewarm('pg_index');
select pg_prewarm('pg_constraint_conrelid_index');
select pg_prewarm('pg_constraint');
select pg_prewarm('pg_class_relname_nsp_index');
select pg_prewarm('pg_class_oid_index');
select pg_prewarm('pg_attribute_relid_attnum_index');
select pg_prewarm('pg_attribute');
select pg_prewarm('pg_attrdef_adrelid_adnum_index');
select pg_prewarm('pg_attrdef');
select pg_prewarm('pg_amproc_fam_proc_index');
select pg_prewarm('pg_namespace_oid_index');
Regards,
Nanda
On 18 Jan 2018 07:25, "Michael Paquier" <michael.paquier@gmail.com> wrote:
On Tue, Jan 16, 2018 at 09:18:25PM -0800, Jeff Janes wrote:
> Oh. I've not seen that before. But then again I don't often restart my
> server and then immediately run very large queries with a stringent time
> deadline.
>
> You can try pg_prewarm, on pg_statistic table and its index. But I'd
> probably just put an entry in my db startup script to run this query
> immediately after startng the server, and let the query warm the cache
> itself.
>
> Why do you restart your database often enough for this to be an issue?
Another thing that you could use here is pg_buffercache which offers a
way to look at the Postgres shared buffer contents in real-time:
https://www.postgresql.org/docs/current/static/pgbuffercache.html
As Jeff says, pg_prewarm is a good tool for such cases to avoid any kind
of warmup period when a server starts..
--
Michael
^ permalink raw reply [nested|flat] 13+ messages in thread
* RE: Query is slow when run for first time; subsequent execution is fast
@ 2018-09-04 07:16 jimmy <mpokky@126.com>
0 siblings, 1 reply; 13+ messages in thread
From: jimmy @ 2018-09-04 07:16 UTC (permalink / raw)
To: m.nanda92@gmail.com; pgsql-performance; guillaume.poussel@sogeti.com; +Cc: jeff.janes@gmail.com
On windows, how to put an entry in my db startup script to run this query （pg_prewarm） immediately after startng the server, and let the query warm the cache itself.
After starting the server, I want to know what is the server, and it is the database I restarted or windows system?
Thank you.
>Hi,
>On 17 Jan 2018 12:55, "POUSSEL, Guillaume" <guillaume(dot)poussel(at)sogeti(dot)com>
>wrote:
>Are you on Windows or Linux? I’m on Windows and wondering if the issue is
>the same on Linux?
>I have experienced this on Mac and Linux machines.
>You can try pg_prewarm, on pg_statistic table and its index. But I'd
>probably just put an entry in my db startup script to run this query
>immediately after startng the server, and let the query warm the cache
>itself.
>I will try this suggestion and get back on the thread. Is pg_statistic the
>only table to be pre cached? Pls let me know if any other table/index needs
>to be pre warmed.
>
>
>Btw, I don't running a "select * from pg_statistic" will fill the shared
>buffer. Only 256 kb of data will be cached during sequential scans. I will
>try pg_prewarm
>
>
>Why do you restart your database often
>
>
>Postgres is bundled with our application and deployed by our client.
>Starting / stopping the server is not under my control.
>
>
>Regards,
>Nanda
^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: Query is slow when run for first time; subsequent execution is fast
@ 2018-09-05 00:35 Jeff Janes <jeff.janes@gmail.com>
parent: jimmy <mpokky@126.com>
0 siblings, 0 replies; 13+ messages in thread
From: Jeff Janes @ 2018-09-05 00:35 UTC (permalink / raw)
To: mpokky@126.com; +Cc: Nandakumar M <m.nanda92@gmail.com>; pgsql-performance; guillaume.poussel@sogeti.com
On Tue, Sep 4, 2018 at 3:16 AM jimmy <mpokky@126.com> wrote:
> On windows, how to put an entry in my db startup script to run this query
> （pg_prewarm） immediately after startng the server, and let the query warm
> the cache itself.
>
Starting with PostgreSQL version 11 (to be released soon), you can use
pg_prewarm.autoprewarm.
Until then, maybe this:
https://superuser.com/questions/502160/run-a-scheduled-task-after-a-windows-service-is-started
I've tested neither one.
Cheers,
Jeff
^ permalink raw reply [nested|flat] 13+ messages in thread
end of thread, other threads:[~2018-09-05 00:35 UTC | newest]
Thread overview: 13+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2018-01-10 11:59 Query is slow when run for first time; subsequent execution is fast Nandakumar M <m.nanda92@gmail.com>
2018-01-10 19:34 ` Jeff Janes <jeff.janes@gmail.com>
2018-01-12 08:03 ` Nandakumar M <m.nanda92@gmail.com>
2018-01-12 10:04 ` Pavel Stehule <pavel.stehule@gmail.com>
2018-01-16 11:46 ` Nandakumar M <m.nanda92@gmail.com>
2018-01-16 12:20 ` Thomas Kellerer <spam_eater@gmx.net>
2018-01-17 05:18 ` Jeff Janes <jeff.janes@gmail.com>
2018-01-17 07:25 ` POUSSEL, Guillaume <guillaume.poussel@sogeti.com>
2018-01-17 10:09 ` Nandakumar M <m.nanda92@gmail.com>
2018-01-18 01:55 ` Michael Paquier <michael.paquier@gmail.com>
2018-01-26 07:43 ` Nandakumar M <m.nanda92@gmail.com>
2018-09-04 07:16 RE: Query is slow when run for first time; subsequent execution is fast jimmy <mpokky@126.com>
2018-09-05 00:35 ` Jeff Janes <jeff.janes@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox