Thread: Moving responsibility for logging "database system is shut down"
In our recent investigations of slow shutdown on some buildfarm members, it became clear that "database system is shut down" can get logged many seconds before the postmaster actually exits; the main cause of delay is that the stats collector's final data dump can take awhile. This is pretty confusing, IMO. I think that that message should only come out once the postmaster has removed its pidfile, which is the action that makes it look shut-down to "pg_ctl stop". After some investigation it seems that the best place to do the logging is right in UnlinkLockFiles(); that's called when and only when we need a log message, and there doesn't seem to be a better place for it. I considered putting the logging into proc_exit(), but then we would need more logic to determine whether the type of process we're exiting is one for which such a message should be printed. That seems messier. I also considered moving the "shutting down" message that is currently printed at the top of ShutdownXLOG(), but could not find any clearly better place to do that than where it is. So I propose the attached patch. Any objections? Should this get back-patched? It's arguably a bug, though surely a minor one, that the message comes out when it does. regards, tom lane diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index a2846c4..07a7679 100644 *** a/src/backend/access/transam/xlog.c --- b/src/backend/access/transam/xlog.c *************** ShutdownXLOG(int code, Datum arg) *** 7948,7957 **** ShutdownCommitTs(); ShutdownSUBTRANS(); ShutdownMultiXact(); - - /* Don't be chatty in standalone mode */ - ereport(IsPostmasterEnvironment ? LOG : NOTICE, - (errmsg("database system is shut down"))); } /* --- 7948,7953 ---- diff --git a/src/backend/utils/init/miscinit.c b/src/backend/utils/init/miscinit.c index b7bab56..603a256 100644 *** a/src/backend/utils/init/miscinit.c --- b/src/backend/utils/init/miscinit.c *************** UnlinkLockFiles(int status, Datum arg) *** 724,729 **** --- 724,740 ---- } /* Since we're about to exit, no need to reclaim storage */ lock_files = NIL; + + /* + * Lock file removal should always be the last externally visible action + * of a postmaster or standalone backend, while we won't come here at all + * when exiting postmaster child processes. Therefore, this is a good + * place to log completion of shutdown. We could alternatively teach + * proc_exit() to do it, but that seems uglier. In a standalone backend, + * use NOTICE elevel to be less chatty. + */ + ereport(IsPostmasterEnvironment ? LOG : NOTICE, + (errmsg("database system is shut down"))); } /*
On Wed, Feb 10, 2016 at 3:13 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > In our recent investigations of slow shutdown on some buildfarm members, > it became clear that "database system is shut down" can get logged many > seconds before the postmaster actually exits; the main cause of delay > is that the stats collector's final data dump can take awhile. This is > pretty confusing, IMO. I think that that message should only come out > once the postmaster has removed its pidfile, which is the action that > makes it look shut-down to "pg_ctl stop". > > After some investigation it seems that the best place to do the logging > is right in UnlinkLockFiles(); that's called when and only when we need > a log message, and there doesn't seem to be a better place for it. > I considered putting the logging into proc_exit(), but then we would need > more logic to determine whether the type of process we're exiting is one > for which such a message should be printed. That seems messier. > > I also considered moving the "shutting down" message that is currently > printed at the top of ShutdownXLOG(), but could not find any clearly > better place to do that than where it is. > > So I propose the attached patch. Any objections? Should this get > back-patched? It's arguably a bug, though surely a minor one, that > the message comes out when it does. I would vote against a back-patch. And I kind of agree with Jim's comments that we ought to consider sprinkling a few more debug messages into the shutdown sequence. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
Robert Haas <robertmhaas@gmail.com> writes: > On Wed, Feb 10, 2016 at 3:13 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: >> So I propose the attached patch. Any objections? Should this get >> back-patched? It's arguably a bug, though surely a minor one, that >> the message comes out when it does. > I would vote against a back-patch. And I kind of agree with Jim's > comments that we ought to consider sprinkling a few more debug > messages into the shutdown sequence. [ shrug... ] I won't stand in the way of someone else figuring out what makes sense there, but I don't intend to do it; and I don't think that the quick hacks I did over the last couple days make a reasonable basis for a permanent patch. regards, tom lane
On 10 February 2016 at 22:39, Tom Lane <tgl@sss.pgh.pa.us> wrote:
--
Robert Haas <robertmhaas@gmail.com> writes:
> On Wed, Feb 10, 2016 at 3:13 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> So I propose the attached patch. Any objections? Should this get
>> back-patched? It's arguably a bug, though surely a minor one, that
>> the message comes out when it does.
> I would vote against a back-patch. And I kind of agree with Jim's
> comments that we ought to consider sprinkling a few more debug
> messages into the shutdown sequence.
[ shrug... ] I won't stand in the way of someone else figuring out
what makes sense there, but I don't intend to do it; and I don't think
that the quick hacks I did over the last couple days make a reasonable
basis for a permanent patch.
I think its worth adding log messages, but only when its slower than expected.
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services