PostgreSQL Hacks - statement

Author

statement_timeout logging

Simon Riggs

2005-09-09, 7:24 am

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_statem
ent 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_statem
ent=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_state
ment > 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_statem
ent...
- 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

Bruce Momjian

2005-09-16, 8:24 pm

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_statem
ent 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_statem
ent=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_state
ment > 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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql
.org so that your
message can get through to the mailing list cleanly

Simon Riggs

2005-09-16, 8:24 pm

> From: Bruce Momjian & #91;mailto:pgman@can
dle.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

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Bruce Momjian

2005-09-16, 8:24 pm

Simon Riggs wrote:
>
> 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_statem
ent that is just above error, but that
seems confusing. I think the right solution would be to allow
log_min_duration_sta
tement to work for canceled queries. Right now,
log_min_duration_sta
tement 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

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Simon Riggs

2005-09-18, 1:26 pm

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_statem
ent that is just above error, but that
> seems confusing. I think the right solution would be to allow
> log_min_duration_sta
tement to work for canceled queries. Right now,
> log_min_duration_sta
tement 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_sta
tement:

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

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Bruce Momjian

2005-09-19, 1:26 pm

Simon Riggs wrote:
> On Fri, 2005-09-16 at 20:48 -0400, Bruce Momjian wrote:
>
> 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_statem
ent. 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_statem
ent = '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_sta
tement:
>
> 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

Simon Riggs

2005-09-21, 1:26 pm

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_statem
ent</> 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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql
.org so that your
message can get through to the mailing list cleanly

Bruce Momjian

2005-09-21, 8:24 pm

Simon Riggs wrote:
> On Mon, 2005-09-19 at 13:21 -0400, Bruce Momjian wrote:
>
>
> Gosh, that says a lot about my code quality. I will strive to improve
> from "actually works" to "works as expected" for future patches.
>
>
>
> 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_statem
ent 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

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Sponsored Links