Re: statement_timeout logging

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.

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.

---

Longer term, we might handle this differently. If we differentiate
between two types of ERROR, at least for log_min_error_statement...
- one that prevents the query from ever running (syntax, parse errors)
- one that occurs because the query itself gets into difficulty, but not
so badly that it constitutes a FATAL error. Lets call it RUNERROR for
now.
I expect most people to want to log RUNERRORs, but to want to ignore the
more normal kind of ERRORs.

When/if we can differentiate between levels, I'll reverse out this patch
since we'll be able to handle it simply with the new errorlevel.

Best Regards, Simon Riggs

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(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

Simon Riggs wrote:
> > From: Bruce Momjian [mailto:pgman(at)candle(dot)pha(dot)pa(dot)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(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

> From: Bruce Momjian [mailto:pgman(at)candle(dot)pha(dot)pa(dot)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

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(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

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(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