Improve logging by reducing noise and logging high-level events

Author: sfc-gh-mslot

duckdb_pglake/src/fs/file_cache_manager.cpp

@@ -464,7 +464,7 @@ FileCacheManager::RemoveCacheFileInternal(FileSystem &file_system, string finalC
 		fileExists = file_system.FileExists(filePath);
 		if (fileExists)
 		{
-			PGDUCK_SERVER_LOG("removing %s from cache", filePath.c_str());
+			PGDUCK_SERVER_DEBUG("removing %s from cache", filePath.c_str());
 			file_system.RemoveFile(filePath);
 		}
 	}
@@ -621,8 +621,8 @@ FileCacheManager::ManageCache(ClientContext &context, int64_t maxCacheSize)
 
 		if (!cacheFile.isCandidate)
 		{
-			PGDUCK_SERVER_LOG("removing %s from cache (%" PRIu64 \
-							  " bytes)", cacheFile.cacheFilePath.c_str(), cacheFile.fileSize);
+			PGDUCK_SERVER_DEBUG("removing %s from cache (%" PRIu64 \
+							    " bytes)", cacheFile.cacheFilePath.c_str(), cacheFile.fileSize);
 
 			/* for background tasks, we skip if lock cannot be acquired */
 			bool waitForLock = false;

pg_lake_copy/src/copy/copy.c

@@ -37,6 +37,7 @@
 #include "pg_lake/copy/copy.h"
 #include "pg_lake/csv/csv_options.h"
 #include "pg_lake/csv/csv_writer.h"
+#include "pg_lake/data_file/data_file_stats.h"
 #include "pg_lake/describe/describe.h"
 #include "pg_lake/extensions/pg_lake_copy.h"
 #include "pg_lake/extensions/pg_parquet.h"
@@ -926,15 +927,32 @@ ProcessPgLakeCopyTo(CopyStmt *copyStmt, ParseState *pstate, Relation relation,
 	/*
 	 * Copy the CSV file to the destination path in the desired format.
 	 */
-	ConvertCSVFileTo(tempCSVPath, tupleDesc, maximumLineLength,
-					 destinationPath, destinationFormat, destinationCompression,
-					 copyStmt->options, schema, NIL);
+	StatsCollector *writeStats =
+		ConvertCSVFileTo(tempCSVPath, tupleDesc, maximumLineLength,
+						 destinationPath, destinationFormat, destinationCompression,
+						 copyStmt->options, schema, NIL);
 
 	if (IsCopyToStdout(copyStmt))
 	{
 		/* send the temporary file in the target format to the client */
 		CopyFileToOutput(destinationPath, tupleDesc->natts, true);
 	}
+	else if (IsSupportedURL(copyStmt->filename) && writeStats != NULL)
+	{
+		int64		totalBytes = 0;
+		ListCell   *cell = NULL;
+
+		foreach(cell, writeStats->dataFileStats)
+		{
+			DataFileStats *fileStats = lfirst(cell);
+
+			totalBytes += fileStats->fileSize;
+		}
+
+		ereport(LOG,
+				(errmsg("pg_lake: wrote " INT64_FORMAT " rows (" INT64_FORMAT " bytes) to %s",
+						writeStats->totalRowCount, totalBytes, copyStmt->filename)));
+	}
 }
 
 

pg_lake_table/include/pg_lake/fdw/writable_table.h

@@ -38,6 +38,24 @@
 
 #define DEFAULT_MIN_INPUT_FILES (5)
 
+/*
+ * CompactionStats aggregates file/byte/row totals across a single VACUUM
+ * compaction run on one table.
+ */
+typedef struct CompactionStats
+{
+	int64		filesRemoved;
+	int64		bytesRemoved;
+	int64		rowsRemoved;
+
+	int64		filesAdded;
+	int64		bytesAdded;
+	int64		rowsAdded;
+
+	/* position-deleted rows materialized away by this compaction */
+	int64		positionDeletedRowsResolved;
+}			CompactionStats;
+
 /*
  * DataFileModificationType reflects a type of modification.
  */
@@ -105,7 +123,8 @@ extern PGDLLEXPORT void ApplyDataFileModifications(Relation rel, List *modificat
 extern PGDLLEXPORT void RemoveAllDataFilesFromTable(Oid relationId);
 extern PGDLLEXPORT void RemoveAllDataFilesFromPgLakeCatalogFromTable(Oid relationId);
 extern PGDLLEXPORT bool CompactDataFiles(Oid relaitonId, TimestampTz compactionStartTime,
-										 bool forceMerge, bool isVerbose);
+										 bool forceMerge, bool isVerbose,
+										 CompactionStats * runStats);
 extern PGDLLEXPORT void CompactMetadata(Oid relationId, bool isVerbose);
 extern PGDLLEXPORT List *GetPositionDeleteFilesForDataFiles(Oid relationId, List *dataFiles,
 															Snapshot snapshot, uint64 *rowCount);

pg_lake_table/src/ddl/create_table.c

@@ -1026,6 +1026,10 @@ ProcessCreateIcebergTableFromForeignTableStmt(ProcessUtilityParams * params)
 
 	ApplyDDLChanges(relationId, ddlOps);
 
+	ereport(LOG,
+			(errmsg("pg_lake: created iceberg table %s at %s",
+					GetQualifiedRelationName(relationId), location)));
+
 	/* signal that we already executed parent process utility */
 	return true;
 }

pg_lake_table/src/ddl/drop_table.c

@@ -291,6 +291,11 @@ DropTableAccessHook(ObjectAccessType access, Oid classId, Oid objectId,
 		}
 		else
 		{
+			char	   *qualifiedName = GetQualifiedRelationName(objectId);
+			char	   *queryArguments = "";
+			char	   *tableLocation = GetWritableTableLocation(objectId, &queryArguments);
+			int64		tableSize = GetTableSizeFromCatalog(objectId);
+
 			/* Cleanup rowid sequence, if we have it */
 			DropRowIdSequenceForRelation(objectId);
 
@@ -306,6 +311,11 @@ DropTableAccessHook(ObjectAccessType access, Oid classId, Oid objectId,
 
 			if (catalogType == REST_CATALOG_READ_WRITE)
 				RecordRestCatalogRequestInTx(objectId, REST_CATALOG_DROP_TABLE, NULL);
+
+			ereport(LOG,
+					(errmsg("pg_lake: dropped iceberg table %s at %s "
+							"(" INT64_FORMAT " bytes)",
+							qualifiedName, tableLocation, tableSize)));
 		}
 	}
 	else if (get_rel_type_id(objectId) != InvalidOid && subId != 0)

pg_lake_table/src/ddl/vacuum.c

@@ -34,6 +34,7 @@
 #include "storage/lmgr.h"
 #include "pg_lake/cleanup/deletion_queue.h"
 #include "pg_lake/cleanup/in_progress_files.h"
+#include "pg_lake/fdw/data_files_catalog.h"
 #include "pg_lake/ddl/utility_hook.h"
 #include "pg_lake/ddl/vacuum.h"
 #include "pg_lake/extensions/pg_lake_iceberg.h"
@@ -670,6 +671,7 @@ VacuumCompactDataFiles(Oid relationId, bool isFull, bool isVerbose)
 {
 	volatile bool continueCompaction = false;
 	int			compactionCount = 0;
+	CompactionStats runStats = {0};
 
 	/*
 	 * Compact files that are created before VACUUM starts. We do this because
@@ -710,7 +712,8 @@ VacuumCompactDataFiles(Oid relationId, bool isFull, bool isVerbose)
 			INJECTION_POINT_COMPAT("compact-files-before-compact");
 
 			/* do compaction */
-			continueCompaction = CompactDataFiles(relationId, compactionStartTime, isFull, isVerbose);
+			continueCompaction = CompactDataFiles(relationId, compactionStartTime,
+												  isFull, isVerbose, &runStats);
 
 			VacuumConsumeTrackedIcebergMetadataChanges(isVerbose);
 
@@ -749,6 +752,26 @@ VacuumCompactDataFiles(Oid relationId, bool isFull, bool isVerbose)
 		compactionCount++;
 	}
 	while (continueCompaction && compactionCount < MaxCompactionsPerVacuum);
+
+	if (runStats.filesRemoved > 0 || runStats.filesAdded > 0)
+	{
+		char	   *positionDeleteSuffix = runStats.positionDeletedRowsResolved > 0
+			? psprintf(", resolved " INT64_FORMAT " position-deleted rows",
+					   runStats.positionDeletedRowsResolved)
+			: "";
+		int64		tableSize = GetTableSizeFromCatalog(relationId);
+
+		ereport(LOG,
+				(errmsg("pg_lake: compacted iceberg table %s: "
+						"rewrote " INT64_FORMAT " files (" INT64_FORMAT " bytes, " INT64_FORMAT " rows) "
+						"into " INT64_FORMAT " files (" INT64_FORMAT " bytes, " INT64_FORMAT " rows)%s; "
+						"table is now " INT64_FORMAT " bytes",
+						GetQualifiedRelationName(relationId),
+						runStats.filesRemoved, runStats.bytesRemoved, runStats.rowsRemoved,
+						runStats.filesAdded, runStats.bytesAdded, runStats.rowsAdded,
+						positionDeleteSuffix,
+						tableSize)));
+	}
 }
 
 
@@ -909,6 +932,18 @@ VacuumRemoveDeletionQueueRecords(Oid relationId, bool isFull, bool isVerbose)
 	while (!isFull				/* when isFull, we'll remove all files */
 		   && totalFilesRemoved < MaxFileRemovalsPerVacuum	/* per-vacuum limit */
 		   && hasRemainingFiles /* no more files to remove */ );
+
+	if (totalFilesRemoved > 0)
+	{
+		if (relationId != InvalidOid)
+			ereport(LOG,
+					(errmsg("pg_lake: expired %d files from iceberg table %s",
+							totalFilesRemoved, GetQualifiedRelationName(relationId))));
+		else
+			ereport(LOG,
+					(errmsg("pg_lake: expired %d files from dropped iceberg tables",
+							totalFilesRemoved)));
+	}
 }
 
 /*
@@ -987,6 +1022,18 @@ VacuumRemoveInProgressFiles(Oid relationId, bool isFull, bool isVerbose)
 	while (!isFull				/* when isFull, we'll remove all files */
 		   && totalFilesRemoved < MaxFileRemovalsPerVacuum	/* per-vacuum limit */
 		   && hasRemainingFiles /* no more files to remove */ );
+
+	if (totalFilesRemoved > 0)
+	{
+		if (relationId != InvalidOid)
+			ereport(LOG,
+					(errmsg("pg_lake: cleaned up %d orphaned files from iceberg table %s",
+							totalFilesRemoved, GetQualifiedRelationName(relationId))));
+		else
+			ereport(LOG,
+					(errmsg("pg_lake: cleaned up %d orphaned files from dropped iceberg tables",
+							totalFilesRemoved)));
+	}
 }
 
 

pg_lake_table/src/fdw/writable_table.c

@@ -113,6 +113,7 @@ static HTAB *GroupDataFilesByPartition(List *dataFiles, TimestampTz compactionSt
 static List *FilterCompactionCandidates(List *dataFiles, TimestampTz compactionStartTime, bool forceMerge,
 										bool forceCompactDeletions);
 static List *TryCompactDataFiles(Oid relationId, TupleDesc tupleDescriptor, List *candidates,
+								 CompactionStats * runStats,
 								 PgLakeTableType tableType, List *options, bool forceMerge, bool isVerbose);
 #ifdef USE_ASSERT_CHECKING
 static void AssertAllFilesHaveSamePartition(List *dataFiles);
@@ -149,7 +150,7 @@ int			TargetFileSizeMB = DEFAULT_TARGET_FILE_SIZE_MB;
 int			VacuumCompactMinInputFiles = DEFAULT_MIN_INPUT_FILES;
 
 /* pg_lake_table.write_log_level */
-int			WriteLogLevel = LOG;
+int			WriteLogLevel = DEBUG1;
 
 
 /*
@@ -710,7 +711,7 @@ RemoveAllDataFilesFromPgLakeCatalogFromTable(Oid relationId)
  */
 bool
 CompactDataFiles(Oid relationId, TimestampTz compactionStartTime,
-				 bool forceMerge, bool isVerbose)
+				 bool forceMerge, bool isVerbose, CompactionStats * runStats)
 {
 	/* prevent concurrent update/delete which might rewrite files too */
 	LockTableForUpdate(relationId);
@@ -765,7 +766,7 @@ CompactDataFiles(Oid relationId, TimestampTz compactionStartTime,
 	}
 
 	List	   *newFileOps = TryCompactDataFiles(relationId, tupleDescriptor, entry->dataFiles,
-												 tableType, options, forceMerge, isVerbose);
+												 runStats, tableType, options, forceMerge, isVerbose);
 
 	table_close(rel, NoLock);
 	PopActiveSnapshot();
@@ -811,6 +812,7 @@ AssertAllFilesHaveSamePartition(List *dataFiles)
  */
 static List *
 TryCompactDataFiles(Oid relationId, TupleDesc tupleDescriptor, List *candidates,
+					CompactionStats * runStats,
 					PgLakeTableType tableType, List *options, bool forceMerge, bool isVerbose)
 {
 #ifdef USE_ASSERT_CHECKING
@@ -867,6 +869,14 @@ TryCompactDataFiles(Oid relationId, TupleDesc tupleDescriptor, List *candidates,
 
 		fileSizeSum += dataFile->stats.fileSize;
 
+		if (runStats != NULL)
+		{
+			runStats->filesRemoved++;
+			runStats->bytesRemoved += dataFile->stats.fileSize;
+			runStats->rowsRemoved += dataFile->stats.rowCount - dataFile->stats.deletedRowCount;
+			runStats->positionDeletedRowsResolved += dataFile->stats.deletedRowCount;
+		}
+
 		filePathsToCompact = lappend(filePathsToCompact, dataFile->path);
 	}
 
@@ -953,6 +963,20 @@ TryCompactDataFiles(Oid relationId, TupleDesc tupleDescriptor, List *candidates,
 
 	metadataOperations = list_concat(metadataOperations, newFileOps);
 
+	if (runStats != NULL)
+	{
+		ListCell   *newFileCell = NULL;
+
+		foreach(newFileCell, newFileOps)
+		{
+			TableMetadataOperation *addOp = lfirst(newFileCell);
+
+			runStats->filesAdded++;
+			runStats->bytesAdded += addOp->dataFileStats.fileSize;
+			runStats->rowsAdded += addOp->dataFileStats.rowCount;
+		}
+	}
+
 	if (hasRowIds)
 	{
 		/* get the row ID ranges from the compacted files */

pg_lake_table/src/init.c

@@ -348,7 +348,7 @@ _PG_init(void)
 							 "additions/removals.",
 							 NULL,
 							 &WriteLogLevel,
-							 LOG,
+							 DEBUG1,
 							 LogLevelOptions,
 							 PGC_SUSET,
 							 GUC_NO_SHOW_ALL | GUC_NOT_IN_SAMPLE,