Thread: Query is slow when run for first time; subsequent execution is fast

Query is slow when run for first time; subsequent execution is fast

From

Nandakumar M

Date:

10 January 2018, 17:59:50

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=#

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)

Buffers: shared hit=1

Planning time: 1.058 ms

Execution time: 0.066 ms

(8 rows)

-- end --

From the above result, it is clear that the query execution is very fast but planning time is high in the first run (468.239 ms).

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? Please let me know how I can make sure the query execution for the first time is fast too.

Thanks and regards,

Nanda

Re: Query is slow when run for first time; subsequent execution is fast

From

Jeff Janes

Date:

11 January 2018, 01:34:17

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

Re: Query is slow when run for first time; subsequent execution is fast

From

Nandakumar M

Date:

12 January 2018, 14:03:32

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

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

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

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

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

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

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

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

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

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

Re: Query is slow when run for first time; subsequent execution is fast

From

Pavel Stehule

Date:

12 January 2018, 16:04:42

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

Fwd: Re: Query is slow when run for first time; subsequent executionis fast

From

Nandakumar M

Date:

16 January 2018, 17:46:03

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

Re: Query is slow when run for first time; subsequent execution isfast

From

Thomas Kellerer

Date:

16 January 2018, 18:20:39

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.

Re: Query is slow when run for first time; subsequent execution is fast

From

Jeff Janes

Date:

17 January 2018, 11:18:25

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

RE: Query is slow when run for first time; subsequent execution isfast

From

"POUSSEL, Guillaume"

Date:

17 January 2018, 13:25:10

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> 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.

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.

Attachment

smime.p7s

RE: Query is slow when run for first time; subsequent execution is fast

From

Nandakumar M

Date:

17 January 2018, 16:09:36

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

Re: Query is slow when run for first time; subsequent execution isfast

From

Michael Paquier

Date:

18 January 2018, 07:55:32

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

Attachment

signature.asc

Re: Query is slow when run for first time; subsequent execution is fast

From

Nandakumar M

Date:

26 January 2018, 13:43:23

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