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

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

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