On Thu, Mar 19, 2015 at 06:59:20PM -0300, Alvaro Herrera wrote:
> Robert Haas wrote:
> > On Thu, Mar 19, 2015 at 10:23 AM, Bruce Momjian <br...@momjian.us> wrote:
>
> > > The issue with CommitTransaction() is that it only _holds_ the signal
> > > --- it doesn't clear it. Now, since there are very few
> > > CHECK_FOR_INTERRUPTS() calls in the typical commit process flow, the
> > > signal is normally erased. However, if log_duration or
> > > log_min_duration_statement are set, they call ereport, which calls
> > > errfinish(), which has a call to CHECK_FOR_INTERRUPTS().
> > >
> > > First attached patch is more surgical and clears a possible cancel
> > > request before we report the query duration in the logs --- this doesn't
> > > affect any after triggers that might include CHECK_FOR_INTERRUPTS()
> > > calls we want to honor.
> > >
> > > Another approach would be to have CommitTransaction() clear any pending
> > > cancel before it calls RESUME_INTERRUPTS(). The second attached patch
> > > takes that approach, and also works.
> >
> > So, either way, what happens if the query cancel shows up just an
> > instant after you clear the flag?
>
> I don't understand why aren't interrupts held until after the commit is
> done -- including across the mentioned ereports.
Uh, I think Robert was thinking of pre-commit triggers at the top of
CommitTransaction() that might take a long time and we might want to
cancel. In fact, he is right that mid-way into CommitTransaction(),
after those pre-commit triggers, we do HOLD_INTERRUPTS(), then set our
clog bit and continue to the bottom of that function. What is happening
is that we don't _clear_ the cancel bit and log_duration is finding the
cancel.
In an ideal world, we would clear the client cancel in
CommitTransaction() and when we do log_duration*, and the attached patch
now does that.
--
Bruce Momjian <br...@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com
+ Everyone has their own god. +
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
new file mode 100644
index 1495bb4..853671f
*** a/src/backend/access/transam/xact.c
--- b/src/backend/access/transam/xact.c
*************** CommitTransaction(void)
*** 1958,1963 ****
--- 1958,1966 ----
*/
s->state = TRANS_DEFAULT;
+ /* We have committed so clear any client cancel. */
+ QueryCancelPending = false;
+
RESUME_INTERRUPTS();
}
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
new file mode 100644
index 33720e8..b797cad
*** a/src/backend/tcop/postgres.c
--- b/src/backend/tcop/postgres.c
*************** exec_simple_query(const char *query_stri
*** 1165,1184 ****
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, was_logged))
{
! case 1:
! ereport(LOG,
! (errmsg("duration: %s ms", msec_str),
! errhidestmt(true)));
! break;
! case 2:
! ereport(LOG,
! (errmsg("duration: %s ms statement: %s",
! msec_str, query_string),
! errhidestmt(true),
! errdetail_execute(parsetree_list)));
! break;
}
if (save_log_statement_stats)
--- 1165,1194 ----
/*
* Emit duration logging if appropriate.
*/
{
! int output_duration_level = check_log_duration(msec_str, was_logged);
!
! if (output_duration_level != 0)
! {
! /* hold client cancel as we have already committed */
! HOLD_CANCEL_INTERRUPTS();
!
! if (output_duration_level == 1)
! ereport(LOG,
! (errmsg("duration: %s ms", msec_str),
! errhidestmt(true)));
! else if (output_duration_level == 2)
! ereport(LOG,
! (errmsg("duration: %s ms statement: %s",
! msec_str, query_string),
! errhidestmt(true),
! errdetail_execute(parsetree_list)));
!
! /* clear client cancel */
! QueryCancelPending = false;
!
! RESUME_CANCEL_INTERRUPTS();
! }
}
if (save_log_statement_stats)
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
