Thread: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Pavel Stehule
Date:
Hi,
the interpretation of slow queries or entries from auto-explain log can be difficult some times, because the the main time of query evaluation is waiting on lock, and this number isn't in related entry. Our situation is little bit difficult, because we have not direct access to PostgreSQL logs, we working with log aggregators. Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Tom Lane
Date:
Pavel Stehule <pavel.stehule@gmail.com> writes:
> We have a patch, that inject logs about the time waiting on locks before
> query execution. This feature helps us lot of, and I hope, it can be
> generally useful.
Doesn't log_lock_waits cover that territory already?
regards, tom lane
Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Pavel Stehule
Date:
2016-02-14 17:46 GMT+01:00 Tom Lane <tgl@sss.pgh.pa.us>:
Pavel Stehule <pavel.stehule@gmail.com> writes:
> We have a patch, that inject logs about the time waiting on locks before
> query execution. This feature helps us lot of, and I hope, it can be
> generally useful.
Doesn't log_lock_waits cover that territory already?
It does. But It creates different log entry - and can be hard to join slow query with log entry sometimes lot of lines before. This proposal is about taking important information comfortably - and log parsing and processing is simpler.
Regards
Pavel
regards, tom lane
Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Jim Nasby
Date:
On 2/14/16 11:24 AM, Pavel Stehule wrote: > > We have a patch, that inject logs about the time waiting on locks before > > query execution. This feature helps us lot of, and I hope, it can be > > generally useful. > > Doesn't log_lock_waits cover that territory already? > > It does. But It creates different log entry - and can be hard to join > slow query with log entry sometimes lot of lines before. This proposal > is about taking important information comfortably - and log parsing and > processing is simpler. I'm all for anything that improves visibility into locking, but it seems like this is more a band-aid than a fix. Certainly any real analysis of logfiles means you're stuck with something like pgBadger. If this would significantly simply pgBadger's job then great, but I don't think that's the case. What would be useful logging-wise is if the log line for the query itself could contain lock wait time, but that doesn't sound like what you're proposing? What I think would be far more useful is adding lock wait time info to pg_stat_statements and maybe pg_stat_*_tables. -- Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX Experts in Analytics, Data Architecture and PostgreSQL Data in Trouble? Get it in Treble! http://BlueTreble.com
Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Pavel Stehule
Date:
2016-02-17 3:43 GMT+01:00 Jim Nasby <Jim.Nasby@bluetreble.com>:
On 2/14/16 11:24 AM, Pavel Stehule wrote:> We have a patch, that inject logs about the time waiting on locks before
> query execution. This feature helps us lot of, and I hope, it can be
> generally useful.
Doesn't log_lock_waits cover that territory already?
It does. But It creates different log entry - and can be hard to join
slow query with log entry sometimes lot of lines before. This proposal
is about taking important information comfortably - and log parsing and
processing is simpler.
I'm all for anything that improves visibility into locking, but it seems like this is more a band-aid than a fix. Certainly any real analysis of logfiles means you're stuck with something like pgBadger. If this would significantly simply pgBadger's job then great, but I don't think that's the case.
What would be useful logging-wise is if the log line for the query itself could contain lock wait time, but that doesn't sound like what you're proposing?
I hope, so I propose this idea. First time I wanted talk about the idea. Next step is the talk about format.
What I think would be far more useful is adding lock wait time info to pg_stat_statements and maybe pg_stat_*_tables.
If we can enhance primary log, auto_explain, then we can do same with pg_stat_statements.
lock statistics in table or database level would be great - it is good simple indicator about application health, but it is for another proposal (and patch). I can propose it, or I can collaborate on it with pleasure.
Regards
Pavel
--
Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX
Experts in Analytics, Data Architecture and PostgreSQL
Data in Trouble? Get it in Treble! http://BlueTreble.com
Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
From
Pavel Stehule
Date:
Hi
What would be useful logging-wise is if the log line for the query itself could contain lock wait time, but that doesn't sound like what you're proposing?I hope, so I propose this idea. First time I wanted talk about the idea. Next step is the talk about format.
Some enhancement should to have two parts:
a) introduce new function GetCurrentStatementStartExecutionTimestamp(). This function can be used for calculation of initial lock waiting duration.
b) introduce new GUC log_min_lock_duration_statement. It is similar to log_min_duration_statement. When any statement waits longer time than this number, then statement is logged similar to other slow statement.
example:
log_min_duration_statement = 1000 .. log any slower than 1sec
log_min_lock_duration_statement = 100 log when waiting is longer than 100 ms
entry in log:
LOG: duration:843 ms start lock duration: 156 ms statement: .....
This logic is simple - for some more complicated models, we can introduce some monitoring logs hooks and complex custom logging can be solved in extension.
When log_min_lock_duration_statement is -1, then "start lock duration" isn't printed to log.
Comments, notes?
Regards
Pavel