Movatterモバイル変換

[0]ホーム
URL:

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

 Sign up
Appearance settings

Commit3971f64

Browse files
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 crittersregularly fail with "postmaster does not shut down" complaints. Maybe theyare just really overloaded, but maybe something else is going on. Hence,instrument pg_ctl to print the current time when it starts waiting forpostmaster shutdown and when it gives up, and add a lot of logging of thecurrent time in the server's checkpoint and shutdown code paths.No attempt has been made to make this pretty. I'm not even totally sureif it will build on Windows, but we'll soon find out.
1 parent0231f83 commit3971f64

File tree

7 files changed

+125
-8
lines changed

7 files changed

+125
-8
lines changed

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

Lines 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
staticvoid
86038616
CheckPointGuts(XLogRecPtrcheckPointRedo,intflags)
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

Lines 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

Lines 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
#ifdefUSE_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
#ifdefUSE_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
#ifdefUSE_SYSTEMD
26612664
sd_notify(0,"STOPPING=1");
26622665
#endif

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

Lines 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

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -691,6 +691,31 @@ GetUserNameFromId(Oid roleid, bool noerr)
691691
returnresult;
692692
}
693693

694+
/*
695+
* Quick hack.
696+
*/
697+
constchar*
698+
current_time_as_str(void)
699+
{
700+
staticcharbuf[128];
701+
structtimevalnow_timeval;
702+
pg_time_tnow;
703+
charmsbuf[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+
returnbuf;
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

Lines 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+
constchar*
953+
current_time_as_str(void)
954+
{
955+
staticcharbuf[128];
956+
structtimevalnow_timeval;
957+
time_tnow;
958+
charmsbuf[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+
returnbuf;
973+
}
974+
949975
staticvoid
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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -448,6 +448,7 @@ extern char *local_preload_libraries_string;
448448
#defineLOCK_FILE_LINE_LISTEN_ADDR6
449449
#defineLOCK_FILE_LINE_SHMEM_KEY7
450450

451+
externconstchar*current_time_as_str(void);
451452
externvoidCreateDataDirLockFile(boolamPostmaster);
452453
externvoidCreateSocketLockFile(constchar*socketfile,boolamPostmaster,
453454
constchar*socketDir);

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp