Re: proposal: enhancing slow query log, and autoexplain log about waiting on lock before query exec time

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