log_duration and log_statement

Hello,

Here are some background information to explain our issue and request.
We are currently planning a migration from PostgreSQL 7.4 to
PostgreSQL 8.1. We work on a medium sized database (2GB) with a rather
important activity (12 millions queries a day with peaks up to 1000
queries/s).
We are analyzing the logs with a tool we developed (namely pgFouine
available on pgFoundry). We currently use the following configuration
for logging:
- log_min_duration_statement = 500 to log the slowest queries
- log_duration to log every query duration and have a global overview
of our database activity (used to generate this sort of graphs:
http://people.openwide.fr/~gsmet/postgresql/graphs.html ).
We cannot log every query as we already generate 1.2GB of logs a day
while only logging the text of one hundredth of the queries so we log
only the duration for the "not so slow" queries.

I didn't notice the log_duration behaviour has changed starting from
8.0 (thanks to oicu for pointing me the 8.0 release notes on
#postgresql) and what we did is not possible anymore with 8.x as
log_duration now only logs the duration for queries logged with
log_statement.

I think the former behaviour can be interesting in our case and
probably for many other people out there who use log analysis tools as
logging only slow queries is not enough to have an overview of the
database activity.
I was thinking about something like log_duration = 'none|logged|all'
which will allow us to switch between:
- none: we don't log the duration (=log_duration=off);
- logged: we log the duration only for logged queries (depending on
log_statement as for 8.0);
- all: we log every duration as 7.4 did before when log_duration was on.

Any comment on this?

Thanks in advance for considering my request.

Regards,

--
Guillaume

On Mon, 2006-03-13 at 23:40 +0100, Guillaume Smet wrote:

> Here are some background information to explain our issue and request.
> We are currently planning a migration from PostgreSQL 7.4 to
> PostgreSQL 8.1. We work on a medium sized database (2GB) with a rather
> important activity (12 millions queries a day with peaks up to 1000
> queries/s).
> We are analyzing the logs with a tool we developed (namely pgFouine
> available on pgFoundry).

Guillaume,

Thanks very much for writing pgFouine. We've been doing our best to
support generation of useful logs for performance analysis, so please
feel free to ask for anything you see a need for.

> We currently use the following configuration
> for logging:
> - log_min_duration_statement = 500 to log the slowest queries
> - log_duration to log every query duration and have a global overview
> of our database activity (used to generate this sort of graphs:
> http://people.openwide.fr/~gsmet/postgresql/graphs.html ).

Interesting results and good graphics too.

I note your graphs don't show missing values: on the bottom graph there
is no data for 7pm and 2am, yet the graph passes directly from 6 to 8pm
as if the figure for 7pm was mid-way between them, rather than zero.

> We cannot log every query as we already generate 1.2GB of logs a day
> while only logging the text of one hundredth of the queries so we log
> only the duration for the "not so slow" queries.

How do you tell the difference between a SELECT and a Write query when
you do not see the text of the query?

> I didn't notice the log_duration behaviour has changed starting from
> 8.0 (thanks to oicu for pointing me the 8.0 release notes on
> #postgresql) and what we did is not possible anymore with 8.x as
> log_duration now only logs the duration for queries logged with
> log_statement.
>
> I think the former behaviour can be interesting in our case and
> probably for many other people out there who use log analysis tools as
> logging only slow queries is not enough to have an overview of the
> database activity.
> I was thinking about something like log_duration = 'none|logged|all'
> which will allow us to switch between:
> - none: we don't log the duration (=log_duration=off);
> - logged: we log the duration only for logged queries (depending on
> log_statement as for 8.0);
> - all: we log every duration as 7.4 did before when log_duration was on.
>
> Any comment on this?

I think I need more persuasion before I see the value of this, but I'm
not going to immediately disregard this either.

Collecting information is interesting, but it must in some way lead to a
rational corrective action. Logging the duration of statements without
recording what they are would tell you there was a problem but make it
difficult to move towards an action rationally. Perhaps I'm
misunderstanding this.

Is the issue that the log volume is too high? We might be able to look
at ways to reduce/compress the log volume for duration/statement
logging.

Another thought might be to provide a random sample of queries. A 10%
sample would be sufficient for your case here and yet would provide a
possibility of deeper analysis also.

Best Regards, Simon Riggs

""Guillaume Smet"" <guillaume(dot)smet(at)gmail(dot)com> wrote
>
> Here are some background information to explain our issue and request.

On a separate issue, seems in pgfouine homepage a typo is there for a while:

What's New
2005-02-11 - pgFouine 0.4.99 released ...
2005-01-10 - pgFouine 0.2.1 released ...

I guess they should read as "2006" :-)

Regards,
Qingqing

On 3/14/06, Qingqing Zhou <zhouqq(at)cs(dot)toronto(dot)edu> wrote:
> I guess they should read as "2006" :-)

Sure. Will fix it this evening. Thanks.

Simon,

On 3/14/06, Simon Riggs <simon(at)2ndquadrant(dot)com> wrote:
> Thanks very much for writing pgFouine. We've been doing our best to
> support generation of useful logs for performance analysis, so please
> feel free to ask for anything you see a need for.

OK. Thanks. I should write something clear about what we need one day
or another.

The two problems I have in mind currently are:
- problem to isolate a transaction as a whole. I mean I'd like to have
something to aggregate the BEGIN; QUERY1; QUERY2; COMMIT; as a whole ;
- problem with the way queries are logged when using PG 8.1 and the
8.1 jdbc driver. All our queries are logged as PREPARE and EXECUTE and
we don't have the variables passed in the log (so no value for $1,
$2... and we have the same problem to aggregate the real time of a
query) but I saw a few threads on -hackers talking about this problem.

> I note your graphs don't show missing values: on the bottom graph there
> is no data for 7pm and 2am, yet the graph passes directly from 6 to 8pm
> as if the figure for 7pm was mid-way between them, rather than zero.

Which is obviouly wrong. I missed it as it's not a common case on our
db. Thanks for the report.

> How do you tell the difference between a SELECT and a Write query when
> you do not see the text of the query?

A SELECT is a query beginning with SELECT. It's far from being perfect
but it works most of the time for our projects.
Our main problem is for queries like SELECT update_tables(); which are
inserts/delete in a stored procedure.
If you know any way to do it better, I'm open to any suggestion.
I don't know if it's possible for the backend to log this sort of information.

> I think I need more persuasion before I see the value of this, but I'm
> not going to immediately disregard this either.
>
> Collecting information is interesting, but it must in some way lead to a
> rational corrective action. Logging the duration of statements without
> recording what they are would tell you there was a problem but make it
> difficult to move towards an action rationally. Perhaps I'm
> misunderstanding this.

IMHO, the duration information are interesting as I can see when my
database is heavily loaded which is not correlated with the http
requests (two levels of cache) or with the server load on this
particular website.
Let's admit we have a slow down between 1am and 2pm. There can be a
lot of reasons for that:
- a lot of selects at this time because we are under heavy load from
our website;
- a lot of updates (cronjobs for example);
- another unknow reason we should try to find.
Having duration for all my queries can help me to understand the
problem as I will know:
- how many queries the database really executed at this particular time;
- how slow they are.
If I don't have a global slow down, perhaps, at this time I have a
specific table locked for an unknown reason.

I agree with you that it won't give me all the information to solve my
problem but _it allows me to detect the problem_ and it can at least
give me guidelines to how I can detect it more accurately.

It also gives us a way to see the evolution from one day to another as
we just operates the database, we don't develop the website.
If I have a boost from 1 million queries a day to 20 millions queries
a day, I won't know it with log_min_duration_statement and I can
detect it if log_duration logs every query.

> Is the issue that the log volume is too high? We might be able to look
> at ways to reduce/compress the log volume for duration/statement
> logging.

Well, I'm not sure we can reduce the size of a syslog log but perhaps
I'm wrong. Our problem is both the volume and the performance drop
introduced by logging.

> Another thought might be to provide a random sample of queries. A 10%
> sample would be sufficient for your case here and yet would provide a
> possibility of deeper analysis also.

Why not but I won't have a global overview just a statistical
information and I'd really like to have this overview without logging
every query with log_statement (which we do sometimes for a few
minutes when we really need more information about a specific
problem).

--
Guillaume

On Tue, Mar 14, 2006 at 08:50:22AM +0000, Simon Riggs wrote:
> Is the issue that the log volume is too high? We might be able to look
> at ways to reduce/compress the log volume for duration/statement
> logging.

ISTM that for performance analysis there's probably a better alternative
than just dumping query statements to a logfile. The information we
really want is stuff like:

WAL sync's per second
Read-only queries per second
Queries that modify data per second
Transactions per second
Blacks written per second (maybe broken down by WAL, heap and index)
etc...

Doesn't really have anything to do with logging query strings passed
into the parser.

I know dtrace could be used to provide this kind of info, but it's only
on Solaris (and eventually FreeBSD). But it should be possible to
provide our own version of that for platforms that don't have something
like dtrace.

Or perhaps there's some entirely different statistics collection method
we could come up with...
--
Jim C. Nasby, Sr. Engineering Consultant jnasby(at)pervasive(dot)com
Pervasive Software http://pervasive.com work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461