Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit 3971f64

Browse filesBrowse files
tglsfdctglsfdc
committed
Temporarily make pg_ctl and server shutdown a whole lot chattier.
This is a quick hack, due to be reverted when its purpose has been served, to try to gather information about why some of the buildfarm critters regularly fail with "postmaster does not shut down" complaints. Maybe they are just really overloaded, but maybe something else is going on. Hence, instrument pg_ctl to print the current time when it starts waiting for postmaster shutdown and when it gives up, and add a lot of logging of the current time in the server's checkpoint and shutdown code paths. No attempt has been made to make this pretty. I'm not even totally sure if it will build on Windows, but we'll soon find out.
1 parent 0231f83 commit 3971f64
Copy full SHA for 3971f64

File tree

Expand file treeCollapse file tree

7 files changed

+125
-8
lines changed
Filter options
Expand file treeCollapse file tree

7 files changed

+125
-8
lines changed

‎src/backend/access/transam/xlog.c

Copy file name to clipboardExpand all lines: src/backend/access/transam/xlog.c
+41-2Lines changed: 41 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7927,7 +7927,7 @@ ShutdownXLOG(int code, Datum arg)
79277927
{
79287928
/* Don't be chatty in standalone mode */
79297929
ereport(IsPostmasterEnvironment ? LOG : NOTICE,
7930-
(errmsg("shutting down")));
7930+
(errmsg("shutting down at %s", current_time_as_str())));
79317931

79327932
if (RecoveryInProgress())
79337933
CreateRestartPoint(CHECKPOINT_IS_SHUTDOWN | CHECKPOINT_IMMEDIATE);
@@ -7943,15 +7943,28 @@ ShutdownXLOG(int code, Datum arg)
79437943
RequestXLogSwitch();
79447944

79457945
CreateCheckPoint(CHECKPOINT_IS_SHUTDOWN | CHECKPOINT_IMMEDIATE);
7946+
7947+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
7948+
"shutdown checkpoint complete at %s",
7949+
current_time_as_str());
79467950
}
79477951
ShutdownCLOG();
7952+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
7953+
"ShutdownCLOG() complete at %s",
7954+
current_time_as_str());
79487955
ShutdownCommitTs();
7956+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
7957+
"ShutdownCommitTs() complete at %s",
7958+
current_time_as_str());
79497959
ShutdownSUBTRANS();
7960+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
7961+
"ShutdownSUBTRANS() complete at %s",
7962+
current_time_as_str());
79507963
ShutdownMultiXact();
79517964

79527965
/* Don't be chatty in standalone mode */
79537966
ereport(IsPostmasterEnvironment ? LOG : NOTICE,
7954-
(errmsg("database system is shut down")));
7967+
(errmsg("database system is shut down at %s", current_time_as_str())));
79557968
}
79567969

79577970
/*
@@ -8602,19 +8615,45 @@ CreateEndOfRecoveryRecord(void)
86028615
static void
86038616
CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
86048617
{
8618+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8619+
"CheckPointGuts starting at %s", current_time_as_str());
86058620
CheckPointCLOG();
8621+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8622+
"CheckPointCLOG() done at %s", current_time_as_str());
86068623
CheckPointCommitTs();
8624+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8625+
"CheckPointCommitTs() done at %s", current_time_as_str());
86078626
CheckPointSUBTRANS();
8627+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8628+
"CheckPointSUBTRANS() done at %s", current_time_as_str());
86088629
CheckPointMultiXact();
8630+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8631+
"CheckPointMultiXact() done at %s", current_time_as_str());
86098632
CheckPointPredicate();
8633+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8634+
"CheckPointPredicate() done at %s", current_time_as_str());
86108635
CheckPointRelationMap();
8636+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8637+
"CheckPointRelationMap() done at %s", current_time_as_str());
86118638
CheckPointReplicationSlots();
8639+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8640+
"CheckPointReplicationSlots() done at %s", current_time_as_str());
86128641
CheckPointSnapBuild();
8642+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8643+
"CheckPointSnapBuild() done at %s", current_time_as_str());
86138644
CheckPointLogicalRewriteHeap();
8645+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8646+
"CheckPointLogicalRewriteHeap() done at %s", current_time_as_str());
86148647
CheckPointBuffers(flags); /* performs all required fsyncs */
8648+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8649+
"CheckPointBuffers() done at %s", current_time_as_str());
86158650
CheckPointReplicationOrigin();
8651+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8652+
"CheckPointReplicationOrigin() done at %s", current_time_as_str());
86168653
/* We deliberately delay 2PC checkpointing as long as possible */
86178654
CheckPointTwoPhase(checkPointRedo);
8655+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
8656+
"CheckPointGuts done at %s", current_time_as_str());
86188657
}
86198658

86208659
/*

‎src/backend/postmaster/autovacuum.c

Copy file name to clipboardExpand all lines: src/backend/postmaster/autovacuum.c
+2-1Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -772,7 +772,8 @@ AutoVacLauncherMain(int argc, char *argv[])
772772
/* Normal exit from the autovac launcher is here */
773773
shutdown:
774774
ereport(LOG,
775-
(errmsg("autovacuum launcher shutting down")));
775+
(errmsg("autovacuum launcher shutting down at %s",
776+
current_time_as_str())));
776777
AutoVacuumShmem->av_launcherpid = 0;
777778

778779
proc_exit(0); /* done */

‎src/backend/postmaster/postmaster.c

Copy file name to clipboardExpand all lines: src/backend/postmaster/postmaster.c
+6-3Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2538,7 +2538,8 @@ pmdie(SIGNAL_ARGS)
25382538
break;
25392539
Shutdown = SmartShutdown;
25402540
ereport(LOG,
2541-
(errmsg("received smart shutdown request")));
2541+
(errmsg("received smart shutdown request at %s",
2542+
current_time_as_str())));
25422543
#ifdef USE_SYSTEMD
25432544
sd_notify(0, "STOPPING=1");
25442545
#endif
@@ -2593,7 +2594,8 @@ pmdie(SIGNAL_ARGS)
25932594
break;
25942595
Shutdown = FastShutdown;
25952596
ereport(LOG,
2596-
(errmsg("received fast shutdown request")));
2597+
(errmsg("received fast shutdown request at %s",
2598+
current_time_as_str())));
25972599
#ifdef USE_SYSTEMD
25982600
sd_notify(0, "STOPPING=1");
25992601
#endif
@@ -2656,7 +2658,8 @@ pmdie(SIGNAL_ARGS)
26562658
break;
26572659
Shutdown = ImmediateShutdown;
26582660
ereport(LOG,
2659-
(errmsg("received immediate shutdown request")));
2661+
(errmsg("received immediate shutdown request at %s",
2662+
current_time_as_str())));
26602663
#ifdef USE_SYSTEMD
26612664
sd_notify(0, "STOPPING=1");
26622665
#endif

‎src/backend/storage/buffer/bufmgr.c

Copy file name to clipboardExpand all lines: src/backend/storage/buffer/bufmgr.c
+13Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1691,6 +1691,10 @@ BufferSync(int flags)
16911691
UnlockBufHdr(bufHdr);
16921692
}
16931693

1694+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
1695+
"BufferSync(%x) beginning to write %d buffers at %s",
1696+
flags, num_to_write, current_time_as_str());
1697+
16941698
if (num_to_write == 0)
16951699
return; /* nothing to do */
16961700

@@ -1745,6 +1749,11 @@ BufferSync(int flags)
17451749
if (num_written >= num_to_write)
17461750
break;
17471751

1752+
if ((num_written % 1024) == 0)
1753+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
1754+
"BufferSync(%x) wrote %d/%d buffers at %s",
1755+
flags, num_written, num_to_write, current_time_as_str());
1756+
17481757
/*
17491758
* Sleep to throttle our I/O rate.
17501759
*/
@@ -1756,6 +1765,10 @@ BufferSync(int flags)
17561765
buf_id = 0;
17571766
}
17581767

1768+
elog(IsPostmasterEnvironment ? LOG : NOTICE,
1769+
"BufferSync(%x) done, wrote %d/%d buffers at %s",
1770+
flags, num_written, num_to_write, current_time_as_str());
1771+
17591772
/*
17601773
* Update checkpoint statistics. As noted above, this doesn't include
17611774
* buffers written by other backends or bgwriter scan.

‎src/backend/utils/init/miscinit.c

Copy file name to clipboardExpand all lines: src/backend/utils/init/miscinit.c
+28Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -691,6 +691,31 @@ GetUserNameFromId(Oid roleid, bool noerr)
691691
return result;
692692
}
693693

694+
/*
695+
* Quick hack.
696+
*/
697+
const char *
698+
current_time_as_str(void)
699+
{
700+
static char buf[128];
701+
struct timeval now_timeval;
702+
pg_time_t now;
703+
char msbuf[8];
704+
705+
gettimeofday(&now_timeval, NULL);
706+
now = (pg_time_t) now_timeval.tv_sec;
707+
708+
pg_strftime(buf, sizeof(buf),
709+
/* leave room for milliseconds... */
710+
"%Y-%m-%d %H:%M:%S %Z",
711+
pg_localtime(&now, log_timezone));
712+
713+
/* 'paste' milliseconds into place... */
714+
sprintf(msbuf, ".%03d", (int) (now_timeval.tv_usec / 1000));
715+
memcpy(buf + 19, msbuf, 4);
716+
717+
return buf;
718+
}
694719

695720
/*-------------------------------------------------------------------------
696721
* Interlock-file support
@@ -724,6 +749,9 @@ UnlinkLockFiles(int status, Datum arg)
724749
}
725750
/* Since we're about to exit, no need to reclaim storage */
726751
lock_files = NIL;
752+
753+
if (IsPostmasterEnvironment)
754+
elog(LOG, "lock files all released at %s", current_time_as_str());
727755
}
728756

729757
/*

‎src/bin/pg_ctl/pg_ctl.c

Copy file name to clipboardExpand all lines: src/bin/pg_ctl/pg_ctl.c
+34-2Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -946,6 +946,32 @@ do_start(void)
946946
}
947947

948948

949+
/*
950+
* Quick hack.
951+
*/
952+
const char *
953+
current_time_as_str(void)
954+
{
955+
static char buf[128];
956+
struct timeval now_timeval;
957+
time_t now;
958+
char msbuf[8];
959+
960+
gettimeofday(&now_timeval, NULL);
961+
now = (time_t) now_timeval.tv_sec;
962+
963+
strftime(buf, sizeof(buf),
964+
/* leave room for milliseconds... */
965+
"%Y-%m-%d %H:%M:%S %Z",
966+
localtime(&now));
967+
968+
/* 'paste' milliseconds into place... */
969+
sprintf(msbuf, ".%03d", (int) (now_timeval.tv_usec / 1000));
970+
memcpy(buf + 19, msbuf, 4);
971+
972+
return buf;
973+
}
974+
949975
static void
950976
do_stop(void)
951977
{
@@ -998,7 +1024,12 @@ do_stop(void)
9981024
"Shutdown will not complete until pg_stop_backup() is called.\n\n"));
9991025
}
10001026

1001-
print_msg(_("waiting for server to shut down..."));
1027+
if (!silent_mode)
1028+
{
1029+
fprintf(stdout, _("waiting for server to shut down at %s..."),
1030+
current_time_as_str());
1031+
fflush(stdout);
1032+
}
10021033

10031034
for (cnt = 0; cnt < wait_seconds; cnt++)
10041035
{
@@ -1015,7 +1046,8 @@ do_stop(void)
10151046
{
10161047
print_msg(_(" failed\n"));
10171048

1018-
write_stderr(_("%s: server does not shut down\n"), progname);
1049+
write_stderr(_("%s: server does not shut down at %s\n"),
1050+
progname, current_time_as_str());
10191051
if (shutdown_mode == SMART_MODE)
10201052
write_stderr(_("HINT: The \"-m fast\" option immediately disconnects sessions rather than\n"
10211053
"waiting for session-initiated disconnection.\n"));

‎src/include/miscadmin.h

Copy file name to clipboardExpand all lines: src/include/miscadmin.h
+1Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -448,6 +448,7 @@ extern char *local_preload_libraries_string;
448448
#define LOCK_FILE_LINE_LISTEN_ADDR 6
449449
#define LOCK_FILE_LINE_SHMEM_KEY 7
450450

451+
extern const char *current_time_as_str(void);
451452
extern void CreateDataDirLockFile(bool amPostmaster);
452453
extern void CreateSocketLockFile(const char *socketfile, bool amPostmaster,
453454
const char *socketDir);

0 commit comments

Comments
0 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.