From 9d94f704e91619236f9c15d5878748b134ee25c3 Mon Sep 17 00:00:00 2001 From: Takashi Menjo Date: Mon, 19 Oct 2020 16:55:12 +0900 Subject: [PATCH v4 6/6] More log when using NVWAL --- src/backend/access/transam/xlog.c | 38 ++++++++++++++++++------------- 1 file changed, 22 insertions(+), 16 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index a3caf85f1f..a6b18aa38a 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -2202,14 +2202,6 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, bool opportunistic) int npages = 0; bool is_firstpage; - if (NvwalAvail) - elog(DEBUG1, "XLogCtl->InitializedUpTo %X/%X; upto %X/%X; opportunistic %s", - (uint32) (XLogCtl->InitializedUpTo >> 32), - (uint32) XLogCtl->InitializedUpTo, - (uint32) (upto >> 32), - (uint32) upto, - opportunistic ? "true" : "false"); - LWLockAcquire(WALBufMappingLock, LW_EXCLUSIVE); /* @@ -2277,7 +2269,8 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, bool opportunistic) * If we use non-volatile WAL buffer, it is a special * but expected case to write the buffer pages out to * segment files, and for simplicity, it is done in - * segment by segment. + * segment by segment. Note that this output would + * cause performance degrade, so we log it later. */ XLogRecPtr OldSegEndPtr; @@ -2294,6 +2287,14 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, bool opportunistic) LWLockRelease(WALWriteLock); WalStats.m_wal_buffers_full++; TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY_DONE(); + + /* Out of critical section, so it's time to log */ + if (NvwalAvail) + { + elog(WARNING, "old segment written to file: up to %X/%X", + (uint32) (WriteRqst.Write >> 32), + (uint32) WriteRqst.Write); + } } /* Re-acquire WALBufMappingLock and retry */ LWLockAcquire(WALBufMappingLock, LW_EXCLUSIVE); @@ -2393,13 +2394,6 @@ AdvanceXLInsertBuffer(XLogRecPtr upto, bool opportunistic) } LWLockRelease(WALBufMappingLock); - if (NvwalAvail) - elog(DEBUG1, "ControlFile->discardedUpTo %X/%X; XLogCtl->InitializedUpTo %X/%X", - (uint32) (ControlFile->discardedUpTo >> 32), - (uint32) ControlFile->discardedUpTo, - (uint32) (XLogCtl->InitializedUpTo >> 32), - (uint32) XLogCtl->InitializedUpTo); - #ifdef WAL_DEBUG if (XLOG_DEBUG && npages > 0) { @@ -4228,11 +4222,23 @@ PreallocNonVolatileXlogBuffer(void) if (newupto <= InitializedUpTo) return; + /* + * Logging that we are starting to preallocate. Yes, we know that we are + * still in a critical section of checkpoint, but we log it because + * preallocating might cause performance degrade. + */ + elog(NOTICE, "preallocate starting: up to %X/%X", + (uint32) (newupto >> 32), (uint32) newupto); + /* * Subtracting XLOG_BLCKSZ is important, because AdvanceXLInsertBuffer * handles the first argument as the beginning of pages, not the end. */ AdvanceXLInsertBuffer(newupto - XLOG_BLCKSZ, false); + + /* Logging that we complete to preallocate */ + elog(NOTICE, "preallocate complete: up to %X/%X", + (uint32) (newupto >> 32), (uint32) newupto); } /* -- 2.25.1