Re: Monitoring query plan cache

From: Andomar <andomar(at)aule(dot)net>
To: pgsql-general(at)postgresql(dot)org
Subject: Re: Monitoring query plan cache
Date: 2014-12-21 15:08:43
Message-ID: 5496E27B.9060803@aule.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Thanks for your reply, I have a follow-up question:
>> c) Can you monitor the query parser as a whole, with stats like
>> parses/sec or cache hits/sec?
> Possibly log_parser_stats/log_planner_stats/log_statement_stats
> would help you. They're pretty old-school though; you'd need to
> write some tool that scans the postmaster log and accumulates the
> stats to get anything very useful out of those features. (It
> could be that somebody's already done that, though --- take a
> look at things like pgFouine.)
>
Below is an example output from log_planner_stats:

LOG: PLANNER STATISTICS
DETAIL: ! system usage stats:
! 0.000132 elapsed 0.000000 user 0.000000 system sec
! [0.181972 user 0.052991 sys total]
! 0/0 [0/248] filesystem blocks in/out
! 0/0 [0/2705] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [1/4249] voluntary/involuntary context switches

How can we tell from this whether the query planner used a cached plan?
Is the example above a hit or a miss?

>> a) Is it possible that Postgres caches the query plans for psql
>> functions, but not for ad-hoc SQL?
> plpgsql functions would cache query plans. Ad-hoc SQL doesn't, unless you
> explicitly make use of prepared queries.

It is not always easy to tell the query type (function, prepared or
ad-hoc.) We use Python in mod_wsgi with psycopg2. The code shows ad-hoc
SQL, but who knows what the many layers between Python and the database do.

As suggested by Erwin Brandstetter on dba.stackexchange.com, I ran a
test with:

cursor.execute("""
load 'auto_explain';
set auto_explain.log_min_duration = 0;
set auto_explain.log_nested_statements = on;
select col1 from table1 where id = %(id)s
""", {'id': 123});
print(curs.fetchone()[0]);

The logging doesn't look like a cached plan, you can see the 123 value
but not a parameter like $1. This suggests Postgres was previously
compiling around 200 queries a second on our production machine. Is that
even possible?

Cheers,
Andomar

In response to

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Adrian Klaver 2014-12-21 15:17:06 Re: pg_dump
Previous Message AlexK987 2014-12-21 00:54:44 Is my understanding of bitmap index scans and recheck cond correct?