Logs fixed

contrib/pg_visibility/pg_visibility.c

@@ -434,8 +434,10 @@ pg_truncate_visibility_map(PG_FUNCTION_ARGS)
 		XLogFlush(lsn);
 	}
 
-	if (BlockNumberIsValid(block))
-		smgrtruncate(RelationGetSmgr(rel), &fork, 1, &old_block, &block);
+	if (BlockNumberIsValid(block)) {
+        uint64 x = 0;
+        smgrtruncate(RelationGetSmgr(rel), &fork, 1, &old_block, &block, &x);
+    }
 
 	END_CRIT_SECTION();
 	MyProc->delayChkptFlags &= ~(DELAY_CHKPT_START | DELAY_CHKPT_COMPLETE);

src/backend/access/heap/heapam_handler.c

@@ -625,7 +625,8 @@ heapam_relation_set_new_filelocator(Relation rel,
 static void
 heapam_relation_nontransactional_truncate(Relation rel)
 {
-	RelationTruncate(rel, 0);
+    uint64 x;
+	RelationTruncate(rel, 0, &x);
 }
 
 static void

src/backend/access/heap/vacuumlazy.c

@@ -456,7 +456,7 @@ static IndexBulkDeleteResult *lazy_cleanup_one_index(Relation indrel,
 													 bool estimated_count,
 													 LVRelState *vacrel);
 static bool should_attempt_truncation(LVRelState *vacrel);
-static void lazy_truncate_heap(LVRelState *vacrel);
+static uint32 lazy_truncate_heap(LVRelState *vacrel, uint64* dropped_buffers_count);
 static BlockNumber count_nondeletable_pages(LVRelState *vacrel,
 											bool *lock_waiter_detected);
 static void dead_items_alloc(LVRelState *vacrel, int nworkers);
@@ -858,8 +858,15 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 	vac_close_indexes(vacrel->nindexes, vacrel->indrels, NoLock);
 
 	/* Optionally truncate rel */
-	if (should_attempt_truncation(vacrel))
-		lazy_truncate_heap(vacrel);
+    uint32 truncations_count = 0;
+    uint64 dropped_buffers_count = 0;
+    TimestampTz truncate_end = 0;
+    TimestampTz truncate_start = 0;
+	if (should_attempt_truncation(vacrel)) {
+        truncate_start = GetCurrentTimestamp();
+        truncations_count = lazy_truncate_heap(vacrel, &dropped_buffers_count);
+        truncate_end = GetCurrentTimestamp();
+    }
 
 	/* Pop the error context stack */
 	error_context_stack = errcallback.previous;
@@ -1012,6 +1019,14 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
 							 vacrel->relnamespace,
 							 vacrel->relname,
 							 vacrel->num_index_scans);
+            long		truncate_secs_dur;
+            int			truncate_usecs_dur;
+            TimestampDifference(truncate_start, truncate_end, &truncate_secs_dur, &truncate_usecs_dur);
+            appendStringInfo(&buf, _("truncate: %u count, %d.%03d s, buffers scan for drop: %llu\n"),
+                             truncations_count,
+                             (int) truncate_secs_dur,
+                             truncate_usecs_dur / 1000,
+                             dropped_buffers_count);
 			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u scanned (%.2f%% of total), %u eagerly scanned\n"),
 							 vacrel->removed_pages,
 							 new_rel_pages,
@@ -3196,13 +3211,14 @@ should_attempt_truncation(LVRelState *vacrel)
 /*
  * lazy_truncate_heap - try to truncate off any empty pages at the end
  */
-static void
-lazy_truncate_heap(LVRelState *vacrel)
+static uint32
+lazy_truncate_heap(LVRelState *vacrel, uint64* dropped_buffers_count)
 {
 	BlockNumber orig_rel_pages = vacrel->rel_pages;
 	BlockNumber new_rel_pages;
 	bool		lock_waiter_detected;
 	int			lock_retry;
+    uint32         truncations_count = 0;
 
 	/* Report that we are now truncating */
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
@@ -3247,7 +3263,7 @@ lazy_truncate_heap(LVRelState *vacrel)
 				ereport(vacrel->verbose ? INFO : DEBUG2,
 						(errmsg("\"%s\": stopping truncate due to conflicting lock request",
 								vacrel->relname)));
-				return;
+				return truncations_count;
 			}
 
 			(void) WaitLatch(MyLatch,
@@ -3273,7 +3289,7 @@ lazy_truncate_heap(LVRelState *vacrel)
 			 * tuple density as existing ones, which is less unlikely.
 			 */
 			UnlockRelation(vacrel->rel, AccessExclusiveLock);
-			return;
+			return truncations_count;
 		}
 
 		/*
@@ -3289,13 +3305,14 @@ lazy_truncate_heap(LVRelState *vacrel)
 		{
 			/* can't do anything after all */
 			UnlockRelation(vacrel->rel, AccessExclusiveLock);
-			return;
+			return truncations_count;
 		}
 
 		/*
 		 * Okay to truncate.
 		 */
-		RelationTruncate(vacrel->rel, new_rel_pages);
+		RelationTruncate(vacrel->rel, new_rel_pages, dropped_buffers_count);
+        truncations_count++;
 
 		/*
 		 * We can release the exclusive lock as soon as we have truncated.
@@ -3320,6 +3337,7 @@ lazy_truncate_heap(LVRelState *vacrel)
 						orig_rel_pages, new_rel_pages)));
 		orig_rel_pages = new_rel_pages;
 	} while (new_rel_pages > vacrel->nonempty_pages && lock_waiter_detected);
+    return truncations_count;
 }
 
 /*

src/backend/access/spgist/spgvacuum.c

@@ -927,7 +927,8 @@ spgvacuumscan(spgBulkDeleteState *bds)
 		BlockNumber lastBlock = num_pages - 1;
 
 		num_pages = bds->lastFilledBlock + 1;
-		RelationTruncate(index, num_pages);
+        uint64 x;
+		RelationTruncate(index, num_pages, &x);
 		bds->stats->pages_removed += lastBlock - bds->lastFilledBlock;
 		bds->stats->pages_deleted -= lastBlock - bds->lastFilledBlock;
 	}

src/backend/catalog/heap.c

@@ -3563,7 +3563,8 @@ RelationTruncateIndexes(Relation heapRelation)
 		/*
 		 * Now truncate the actual file (and discard buffers).
 		 */
-		RelationTruncate(currentIndex, 0);
+        uint64 x;
+		RelationTruncate(currentIndex, 0, &x);
 
 		/* Initialize the index and rebuild */
 		/* Note: we do not need to re-establish pkey setting */

src/backend/catalog/storage.c

@@ -286,7 +286,7 @@ RelationPreserveStorage(RelFileLocator rlocator, bool atCommit)
  * dropped.
  */
 void
-RelationTruncate(Relation rel, BlockNumber nblocks)
+RelationTruncate(Relation rel, BlockNumber nblocks, uint64* dropped_buffers_count)
 {
 	bool		fsm;
 	bool		vm;
@@ -419,7 +419,7 @@ RelationTruncate(Relation rel, BlockNumber nblocks)
 	 * longer exist after truncation is complete, and then truncate the
 	 * corresponding files on disk.
 	 */
-	smgrtruncate(RelationGetSmgr(rel), forks, nforks, old_blocks, blocks);
+	smgrtruncate(RelationGetSmgr(rel), forks, nforks, old_blocks, blocks, dropped_buffers_count);
 
 	END_CRIT_SECTION();
 
@@ -1075,7 +1075,8 @@ smgr_redo(XLogReaderState *record)
 		if (nforks > 0)
 		{
 			START_CRIT_SECTION();
-			smgrtruncate(reln, forks, nforks, old_blocks, blocks);
+            uint64 x = 0;
+			smgrtruncate(reln, forks, nforks, old_blocks, blocks, &x);
 			END_CRIT_SECTION();
 		}
 

src/backend/storage/buffer/bufmgr.c

@@ -4529,7 +4529,7 @@ BufferGetLSNAtomic(Buffer buffer)
  *		relation into buffers.
  * --------------------------------------------------------------------
  */
-void
+uint64
 DropRelationBuffers(SMgrRelation smgr_reln, ForkNumber *forkNum,
 					int nforks, BlockNumber *firstDelBlock)
 {
@@ -4550,7 +4550,7 @@ DropRelationBuffers(SMgrRelation smgr_reln, ForkNumber *forkNum,
 				DropRelationLocalBuffers(rlocator.locator, forkNum[j],
 										 firstDelBlock[j]);
 		}
-		return;
+		return 0;
 	}
 
 	/*
@@ -4600,7 +4600,7 @@ DropRelationBuffers(SMgrRelation smgr_reln, ForkNumber *forkNum,
 		for (j = 0; j < nforks; j++)
 			FindAndDropRelationBuffers(rlocator.locator, forkNum[j],
 									   nForkBlock[j], firstDelBlock[j]);
-		return;
+		return nBlocksToInvalidate;
 	}
 
 	for (i = 0; i < NBuffers; i++)
@@ -4642,6 +4642,7 @@ DropRelationBuffers(SMgrRelation smgr_reln, ForkNumber *forkNum,
 		if (j >= nforks)
 			UnlockBufHdr(bufHdr, buf_state);
 	}
+    return (uint64) NBuffers;
 }
 
 /* ---------------------------------------------------------------------

src/backend/storage/smgr/smgr.c

@@ -873,16 +873,15 @@ smgrnblocks_cached(SMgrRelation reln, ForkNumber forknum)
  */
 void
 smgrtruncate(SMgrRelation reln, ForkNumber *forknum, int nforks,
-			 BlockNumber *old_nblocks, BlockNumber *nblocks)
+			 BlockNumber *old_nblocks, BlockNumber *nblocks, uint64* dropped_buffers_count)
 {
 	int			i;
 
 	/*
 	 * Get rid of any buffers for the about-to-be-deleted blocks. bufmgr will
 	 * just drop them without bothering to write the contents.
 	 */
-	DropRelationBuffers(reln, forknum, nforks, nblocks);
-
+    *dropped_buffers_count += DropRelationBuffers(reln, forknum, nforks, nblocks);
 	/*
 	 * Send a shared-inval message to force other backends to close any smgr
 	 * references they may have for this rel.  This is useful because they

src/backend/utils/misc/pg_rusage.c

@@ -61,13 +61,13 @@ pg_rusage_show(const PGRUsage *ru0)
 	}
 
 	snprintf(result, sizeof(result),
-			 _("CPU: user: %d.%02d s, system: %d.%02d s, elapsed: %d.%02d s"),
+			 _("CPU: user: %d.%03d s, system: %d.%03d s, elapsed: %d.%03d s"),
 			 (int) (ru1.ru.ru_utime.tv_sec - ru0->ru.ru_utime.tv_sec),
-			 (int) (ru1.ru.ru_utime.tv_usec - ru0->ru.ru_utime.tv_usec) / 10000,
+			 (int) (ru1.ru.ru_utime.tv_usec - ru0->ru.ru_utime.tv_usec) / 1000,
 			 (int) (ru1.ru.ru_stime.tv_sec - ru0->ru.ru_stime.tv_sec),
-			 (int) (ru1.ru.ru_stime.tv_usec - ru0->ru.ru_stime.tv_usec) / 10000,
+			 (int) (ru1.ru.ru_stime.tv_usec - ru0->ru.ru_stime.tv_usec) / 1000,
 			 (int) (ru1.tv.tv_sec - ru0->tv.tv_sec),
-			 (int) (ru1.tv.tv_usec - ru0->tv.tv_usec) / 10000);
+			 (int) (ru1.tv.tv_usec - ru0->tv.tv_usec) / 1000);
 
 	return result;
 }

src/include/catalog/storage.h

@@ -28,7 +28,7 @@ extern SMgrRelation RelationCreateStorage(RelFileLocator rlocator,
 extern void RelationDropStorage(Relation rel);
 extern void RelationPreserveStorage(RelFileLocator rlocator, bool atCommit);
 extern void RelationPreTruncate(Relation rel);
-extern void RelationTruncate(Relation rel, BlockNumber nblocks);
+extern void RelationTruncate(Relation rel, BlockNumber nblocks, uint64* dropped_buffers_count);
 extern void RelationCopyStorage(SMgrRelation src, SMgrRelation dst,
 								ForkNumber forkNum, char relpersistence);
 extern bool RelFileLocatorSkippingWAL(RelFileLocator rlocator);

src/include/storage/bufmgr.h

@@ -273,7 +273,7 @@ extern void CreateAndCopyRelationData(RelFileLocator src_rlocator,
 									  RelFileLocator dst_rlocator,
 									  bool permanent);
 extern void FlushDatabaseBuffers(Oid dbid);
-extern void DropRelationBuffers(struct SMgrRelationData *smgr_reln,
+extern uint64 DropRelationBuffers(struct SMgrRelationData *smgr_reln,
 								ForkNumber *forkNum,
 								int nforks, BlockNumber *firstDelBlock);
 extern void DropRelationsAllBuffers(struct SMgrRelationData **smgr_reln,

src/include/storage/smgr.h

@@ -114,7 +114,7 @@ extern BlockNumber smgrnblocks(SMgrRelation reln, ForkNumber forknum);
 extern BlockNumber smgrnblocks_cached(SMgrRelation reln, ForkNumber forknum);
 extern void smgrtruncate(SMgrRelation reln, ForkNumber *forknum, int nforks,
 						 BlockNumber *old_nblocks,
-						 BlockNumber *nblocks);
+						 BlockNumber *nblocks, uint64* dropped_buffers_count);
 extern void smgrimmedsync(SMgrRelation reln, ForkNumber forknum);
 extern void smgrregistersync(SMgrRelation reln, ForkNumber forknum);
 extern void AtEOXact_SMgr(void);