proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time
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.
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.
Is this feature interesting for community? What do you think about it?
Regards
Pavel
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
Show quoted text
regards, tom lane
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
Show quoted text
--
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
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