Re: statement_timeout logging

Simon Riggs wrote:
> On Fri, 2005-09-16 at 20:48 -0400, Bruce Momjian wrote:
> > We can go three ways. We can add a boolean GUC to control printing of
> > the query during a timeout, but that seems like overkill. We can add a
> > new level for log_min_error_statement that is just above error, but that
> > seems confusing. I think the right solution would be to allow
> > log_min_duration_statement to work for canceled queries. Right now,
> > log_min_duration_statement doesn't work for canceled queries because the
> > query never completes to give a final duration and hit the test code.
> > Should that be fixed now or added to the TODO list?
>
> The last one seems the right way to go.

OK. I tested it and it actually works, and I added documentation
suggesting its usage. I was a little confused above because the
STATEMENT: line is only output to the server logs because of the way
elog.c handles a STATEMENT print for log_min_error_statement. It does
not output to the client no matter what log_min_messages is set to, and
if someone is concerned about that we can fix it. Technically STATEMENT
is not a log level message.

So, if I do:

test=> SET statement_timeout = 1;
SET
test=> SET log_min_error_statement = 'ERROR';
SET
test=> SELECT * FROM pg_class;
ERROR: canceling statement due to statement timeout

in the logs I see:

ERROR: canceling statement due to statement timeout
STATEMENT: select * from pg_class;

> So, reformat the message at statement_timeout, so that the log looks
> exactly like log_min_duration_statement:
>
> e.g.
>
> LOG: statement_timeout has been activated to cancel statement
> LOG: duration 1625652ms statement SELECT * from bigOne
> LOG: query has been cancelled by user action

Not really. The problem here is that the last line is wrong --- it was
not cancelled by user action. The attached, applied patch adds a
"cancel_from_timeout" variable that properly records if the cancel was
because of a timeout or user interaction, and displays the proper log
message.

> Perhaps we should change the message from kill() to be "statement"
> rather than "query" also...

kill() is the wrong place to print the message. You will see the
attached patch does it in a cleaner way.

> I'd vote fix now, but I guess that seems to be becoming a regular
> viewpoint from me.

OK, fixed.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073