Thread: 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.smet@gmail.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@cs.toronto.edu> wrote: > I guess they should read as "2006" :-) Sure. Will fix it this evening. Thanks.
Simon, On 3/14/06, Simon Riggs <simon@2ndquadrant.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@pervasive.com Pervasive Software http://pervasive.com work: 512-231-6117 vcard: http://jim.nasby.net/pervasive.vcf cell: 512-569-9461