statement_timeout logging

Simon Riggs wrote:

Currently, when we set a statement_timeout and a query runs over that
time there is no log message to say that the statement has timed out. We
do get a message which says
ERROR: canceling query due to user request
and so in the server log it is impossible to tell the difference between
a query that has been cancelled deliberately by the user and a query
whose time(out) has come.

I have updated the message to:

errmsg("canceling query due to user request or statement timeout")));

The timeout causes the query to be cancelled, which is an ERROR, so it
is possible that the query will be logged if log_min_error_statement is
set to ERROR or below. Again, there is no way to tell the difference
between an ERROR statement that has occurred during execution and an
ERROR statement that is generated by a syntax error. So, if you do set
log_min_error_statement=ERROR then you get swamped by syntax errors
rather than being able to see statement timeouts.

Logging these queries ought to be a valuable source of tuning
information, but as a result of the above, this is not currently the
case.

For now, I've written a quick patch to the log the query text with a
suitable error message.

I expect some debate as to whether the line
if (log_min_error_statement > WARNING)
should be there at all, so comments are sought.

I don't see why printing the query cancel from a timeout is any more
special than a user request for cancel or a simple query error. If
users want statements to be printed on error, they will configure things
that way, if not, we should not print them.

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

pgman wrote:

Simon Riggs wrote:

Currently, when we set a statement_timeout and a query runs over that
time there is no log message to say that the statement has timed out. We
do get a message which says
ERROR: canceling query due to user request
and so in the server log it is impossible to tell the difference between
a query that has been cancelled deliberately by the user and a query
whose time(out) has come.

I have updated the message to:

errmsg("canceling query due to user request or statement timeout")));

Oops. Did we freeze the message strings already for this release?

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

On Fri, Sep 16, 2005 at 03:41:11PM -0400, Bruce Momjian wrote:

pgman wrote:

I have updated the message to:

errmsg("canceling query due to user request or statement timeout")));

Oops. Did we freeze the message strings already for this release?

Not yet.

I'm not sure I agree with the wording though -- is there no way to tell
the difference?

--
Alvaro Herrera -- Valdivia, Chile Architect, www.EnterpriseDB.com
"No single strategy is always right (Unless the boss says so)"
(Larry Wall)

Simon Riggs wrote:

From: Bruce Momjian [mailto:pgman@candle.pha.pa.us]
I don't see why printing the query cancel from a timeout is any more
special than a user request for cancel or a simple query error. If
users want statements to be printed on error, they will
configure things
that way, if not, we should not print them.

The log is for admins, not users.

If an admin sets statement_timeout, then it is a good idea to have the
SQL logged as a way of gaining performance information for the *admin*,
who knows less about what users do, yet is still charged with the need
to tune if one user is effecting other users/jobs. That's a different
scenario than a user cancelling their query. The user knows they've
cancelled it, so they already know the SQL and can ask the admin if they
want it faster. Generally the admin doesn't care if a user cancelled a
query, since it might be for a whole host of reasons, whereas a query
cancelled for statement_timeout has one specific cause.

So, I still want this functionality, so the "bad" query is in the logs.

Well, the user can use use statement_timeout too, so it isn't just the
admin. Also, logging queries can be a security issue, so the idea of
logging the query on duration timeout by default seems like a bad idea.

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?

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

Simon Riggs wrote:

Alvaro Herrera
On Fri, Sep 16, 2005 at 03:41:11PM -0400, Bruce Momjian wrote:

I have updated the message to:

errmsg("canceling query due to user request or

statement timeout")));

Oops. Did we freeze the message strings already for this release?

Not yet.

I'm not sure I agree with the wording though -- is there no
way to tell
the difference?

Yes, my patch. :-)

The message is generated following receipt of a SIGINT which is sent by
kill() after the statement_timeout.

My patch was able to generate a different message by logging just before
the kill() is called. (Obviously, there isn't much "after" in this
circumstance).

Your patch just prints a statement "before" printing the cancel message.
What we should do is to print the proper cause of the cancel, and I am
working on a patch for that.

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

From: Bruce Momjian [mailto:pgman@candle.pha.pa.us]
I don't see why printing the query cancel from a timeout is any more
special than a user request for cancel or a simple query error. If
users want statements to be printed on error, they will
configure things
that way, if not, we should not print them.

The log is for admins, not users.

If an admin sets statement_timeout, then it is a good idea to have the
SQL logged as a way of gaining performance information for the *admin*,
who knows less about what users do, yet is still charged with the need
to tune if one user is effecting other users/jobs. That's a different
scenario than a user cancelling their query. The user knows they've
cancelled it, so they already know the SQL and can ask the admin if they
want it faster. Generally the admin doesn't care if a user cancelled a
query, since it might be for a whole host of reasons, whereas a query
cancelled for statement_timeout has one specific cause.

So, I still want this functionality, so the "bad" query is in the logs.

Best Regards, Simon Riggs

Alvaro Herrera
On Fri, Sep 16, 2005 at 03:41:11PM -0400, Bruce Momjian wrote:

I have updated the message to:

errmsg("canceling query due to user request or

statement timeout")));

Oops. Did we freeze the message strings already for this release?

Not yet.

I'm not sure I agree with the wording though -- is there no
way to tell
the difference?

Yes, my patch. :-)

The message is generated following receipt of a SIGINT which is sent by
kill() after the statement_timeout.

My patch was able to generate a different message by logging just before
the kill() is called. (Obviously, there isn't much "after" in this
circumstance).

Best Regards, Simon Riggs

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.

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

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

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

Best Regards, Simon Riggs

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@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

On Mon, 2005-09-19 at 13:21 -0400, Bruce Momjian wrote:

OK. I tested it and it actually works

Gosh, that says a lot about my code quality. I will strive to improve
from "actually works" to "works as expected" for future patches.

and I added documentation
suggesting its usage.

! If <varname>log_min_error_statement</> is set to
! <literal>ERROR</> or lower, the statement that timed out will also be

Might I suggest "Even if" rather than "if"?

Best Regards, Simon Riggs

Simon Riggs wrote:

On Mon, 2005-09-19 at 13:21 -0400, Bruce Momjian wrote:

OK. I tested it and it actually works

Gosh, that says a lot about my code quality. I will strive to improve
from "actually works" to "works as expected" for future patches.

and I added documentation
suggesting its usage.

! If <varname>log_min_error_statement</> is set to
! <literal>ERROR</> or lower, the statement that timed out will also be

Might I suggest "Even if" rather than "if"?

I don't see why "even if" makes sense here. There is no expectation
that log_min_error_statement wouldn't work as documented. I am more
suggesting that it is a nifity way to use the option.

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