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
[email protected] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.17
diff -c -c -r1.17 config.sgml
*** doc/src/sgml/config.sgml 13 Sep 2005 15:24:56 -0000 1.17
--- doc/src/sgml/config.sgml 19 Sep 2005 16:58:53 -0000
***************
*** 3232,3238 ****
<listitem>
<para>
Abort any statement that takes over the specified number of
! milliseconds. A value of zero (the default) turns off the limitation.
</para>
</listitem>
</varlistentry>
--- 3232,3241 ----
<listitem>
<para>
Abort any statement that takes over the specified number of
! milliseconds. If <varname>log_min_error_statement</> is set to
! <literal>ERROR</> or lower, the statement that timed out will also be
! logged. A value of zero (the default) turns off the
! limitation.
</para>
</listitem>
</varlistentry>
Index: src/backend/storage/lmgr/proc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v
retrieving revision 1.163
diff -c -c -r1.163 proc.c
*** src/backend/storage/lmgr/proc.c 20 Aug 2005 23:26:24 -0000 1.163
--- src/backend/storage/lmgr/proc.c 19 Sep 2005 16:58:55 -0000
***************
*** 78,83 ****
--- 78,84 ----
/* Mark these volatile because they can be changed by signal handler */
static volatile bool statement_timeout_active = false;
static volatile bool deadlock_timeout_active = false;
+ volatile bool cancel_from_timeout = false;
/* statement_fin_time is valid only if statement_timeout_active is true */
static struct timeval statement_fin_time;
***************
*** 1058,1063 ****
--- 1059,1065 ----
Assert(!deadlock_timeout_active);
statement_fin_time = fin_time;
statement_timeout_active = true;
+ cancel_from_timeout = false;
}
else if (statement_timeout_active)
{
***************
*** 1128,1141 ****
MemSet(&timeval, 0, sizeof(struct itimerval));
if (setitimer(ITIMER_REAL, &timeval, NULL))
{
! statement_timeout_active = deadlock_timeout_active =
false;
return false;
}
#else
/* BeOS doesn't have setitimer, but has set_alarm */
if (set_alarm(B_INFINITE_TIMEOUT, B_PERIODIC_ALARM) < 0)
{
! statement_timeout_active = deadlock_timeout_active =
false;
return false;
}
#endif
--- 1130,1147 ----
MemSet(&timeval, 0, sizeof(struct itimerval));
if (setitimer(ITIMER_REAL, &timeval, NULL))
{
! statement_timeout_active = false;
! cancel_from_timeout = false;
! deadlock_timeout_active = false;
return false;
}
#else
/* BeOS doesn't have setitimer, but has set_alarm */
if (set_alarm(B_INFINITE_TIMEOUT, B_PERIODIC_ALARM) < 0)
{
! statement_timeout_active = false;
! cancel_from_timeout = false;
! deadlock_timeout_active = false;
return false;
}
#endif
***************
*** 1146,1152 ****
--- 1152,1161 ----
/* Cancel or reschedule statement timeout */
if (is_statement_timeout)
+ {
statement_timeout_active = false;
+ cancel_from_timeout = false;
+ }
else if (statement_timeout_active)
{
if (!CheckStatementTimeout())
***************
*** 1179,1184 ****
--- 1188,1194 ----
{
/* Time to die */
statement_timeout_active = false;
+ cancel_from_timeout = true;
kill(MyProcPid, SIGINT);
}
else
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.459
diff -c -c -r1.459 postgres.c
*** src/backend/tcop/postgres.c 16 Sep 2005 19:31:04 -0000 1.459
--- src/backend/tcop/postgres.c 19 Sep 2005 16:58:58 -0000
***************
*** 1979,1985 ****
/* Set statement timeout running, if any */
if (StatementTimeout > 0)
enable_sig_alarm(StatementTimeout, true);
!
xact_started = true;
}
}
--- 1979,1987 ----
/* Set statement timeout running, if any */
if (StatementTimeout > 0)
enable_sig_alarm(StatementTimeout, true);
! else
! cancel_from_timeout = false;
!
xact_started = true;
}
}
***************
*** 2203,2211 ****
ImmediateInterruptOK = false; /* not idle anymore */
DisableNotifyInterrupt();
DisableCatchupInterrupt();
! ereport(ERROR,
! (errcode(ERRCODE_QUERY_CANCELED),
! errmsg("canceling query due to user request or
statement timeout")));
}
/* If we get here, do nothing (probably, QueryCancelPending was reset)
*/
}
--- 2205,2218 ----
ImmediateInterruptOK = false; /* not idle anymore */
DisableNotifyInterrupt();
DisableCatchupInterrupt();
! if (cancel_from_timeout)
! ereport(ERROR,
! (errcode(ERRCODE_QUERY_CANCELED),
! errmsg("canceling statement due to
statement timeout")));
! else
! ereport(ERROR,
! (errcode(ERRCODE_QUERY_CANCELED),
! errmsg("canceling statement due to
user request")));
}
/* If we get here, do nothing (probably, QueryCancelPending was reset)
*/
}
Index: src/include/storage/proc.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/storage/proc.h,v
retrieving revision 1.81
diff -c -c -r1.81 proc.h
*** src/include/storage/proc.h 20 Aug 2005 23:26:34 -0000 1.81
--- src/include/storage/proc.h 19 Sep 2005 16:58:59 -0000
***************
*** 117,122 ****
--- 117,124 ----
extern int DeadlockTimeout;
extern int StatementTimeout;
+ extern volatile bool cancel_from_timeout;
+
/*
* Function Prototypes
Index: src/test/regress/expected/prepared_xacts.out
===================================================================
RCS file: /cvsroot/pgsql/src/test/regress/expected/prepared_xacts.out,v
retrieving revision 1.2
diff -c -c -r1.2 prepared_xacts.out
*** src/test/regress/expected/prepared_xacts.out 16 Sep 2005 19:39:02
-0000 1.2
--- src/test/regress/expected/prepared_xacts.out 19 Sep 2005 16:59:00
-0000
***************
*** 159,165 ****
-- pxtest3 should be locked because of the pending DROP
set statement_timeout to 1000;
SELECT * FROM pxtest3;
! ERROR: canceling query due to user request or statement timeout
reset statement_timeout;
-- Disconnect, we will continue testing in a different backend
\c -
--- 159,165 ----
-- pxtest3 should be locked because of the pending DROP
set statement_timeout to 1000;
SELECT * FROM pxtest3;
! ERROR: canceling statement due to statement timeout
reset statement_timeout;
-- Disconnect, we will continue testing in a different backend
\c -
***************
*** 174,180 ****
-- pxtest3 should still be locked because of the pending DROP
set statement_timeout to 1000;
SELECT * FROM pxtest3;
! ERROR: canceling query due to user request or statement timeout
reset statement_timeout;
-- Commit table creation
COMMIT PREPARED 'regress-one';
--- 174,180 ----
-- pxtest3 should still be locked because of the pending DROP
set statement_timeout to 1000;
SELECT * FROM pxtest3;
! ERROR: canceling statement due to statement timeout
reset statement_timeout;
-- Commit table creation
COMMIT PREPARED 'regress-one';
---------------------------(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
