Use more reasonable log level when logging compression progress

Don't use LOG log level when printing out non-actionable progress information regarding compression. Fixes #7280 (cherry picked from commit 8775c84)
timescale · Oct 18, 2024 · dee26e8 · dee26e8
1 parent 23d894c
commit dee26e8
Show file tree

Hide file tree

Showing 8 changed files with 150 additions and 185 deletions.
diff --git a/.unreleased/pr_7335 b/.unreleased/pr_7335
@@ -0,0 +1,2 @@
+Fixes: #7335 Change log level used in compression
+Thanks: @gmilamjr for reporting an issue with the log level of compression messages
diff --git a/tsl/src/compression/api.c b/tsl/src/compression/api.c
@@ -398,7 +398,7 @@ compress_chunk_impl(Oid hypertable_relid, Oid chunk_relid)
 	compresschunkcxt_init(&cxt, hcache, hypertable_relid, chunk_relid);
 
 	/* acquire locks on src and compress hypertable and src chunk */
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("acquiring locks for compressing \"%s.%s\"",
 					get_namespace_name(get_rel_namespace(chunk_relid)),
 					get_rel_name(chunk_relid))));
@@ -408,7 +408,7 @@ compress_chunk_impl(Oid hypertable_relid, Oid chunk_relid)
 
 	/* acquire locks on catalog tables to keep till end of txn */
 	LockRelationOid(catalog_get_table_id(ts_catalog_get(), CHUNK), RowExclusiveLock);
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("locks acquired for compressing \"%s.%s\"",
 					get_namespace_name(get_rel_namespace(chunk_relid)),
 					get_rel_name(chunk_relid))));
@@ -441,7 +441,7 @@ compress_chunk_impl(Oid hypertable_relid, Oid chunk_relid)
 		/* create compressed chunk and a new table */
 		compress_ht_chunk = create_compress_chunk(cxt.compress_ht, cxt.srcht_chunk, InvalidOid);
 		new_compressed_chunk = true;
-		ereport(LOG,
+		ereport(DEBUG1,
 				(errmsg("new compressed chunk \"%s.%s\" created",
 						NameStr(compress_ht_chunk->fd.schema_name),
 						NameStr(compress_ht_chunk->fd.table_name))));
@@ -452,7 +452,7 @@ compress_chunk_impl(Oid hypertable_relid, Oid chunk_relid)
 		/* use an existing compressed chunk to compress into */
 		compress_ht_chunk = ts_chunk_get_by_id(mergable_chunk->fd.compressed_chunk_id, true);
 		result_chunk_id = mergable_chunk->table_id;
-		ereport(LOG,
+		ereport(DEBUG1,
 				(errmsg("merge into existing compressed chunk \"%s.%s\"",
 						NameStr(compress_ht_chunk->fd.schema_name),
 						NameStr(compress_ht_chunk->fd.table_name))));
@@ -590,7 +590,7 @@ decompress_chunk_impl(Chunk *uncompressed_chunk, bool if_compressed)
 	ts_chunk_validate_chunk_status_for_operation(uncompressed_chunk, CHUNK_DECOMPRESS, true);
 	compressed_chunk = ts_chunk_get_by_id(uncompressed_chunk->fd.compressed_chunk_id, true);
 
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("acquiring locks for decompressing \"%s.%s\"",
 					NameStr(uncompressed_chunk->fd.schema_name),
 					NameStr(uncompressed_chunk->fd.table_name))));
@@ -617,7 +617,7 @@ decompress_chunk_impl(Chunk *uncompressed_chunk, bool if_compressed)
 
 	/* acquire locks on catalog tables to keep till end of txn */
 	LockRelationOid(catalog_get_table_id(ts_catalog_get(), CHUNK), RowExclusiveLock);
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("locks acquired for decompressing \"%s.%s\"",
 					NameStr(uncompressed_chunk->fd.schema_name),
 					NameStr(uncompressed_chunk->fd.table_name))));
@@ -1152,12 +1152,12 @@ recompress_chunk_segmentwise_impl(Chunk *uncompressed_chunk)
 	 */
 	if (ts_chunk_clear_status(uncompressed_chunk,
 							  CHUNK_STATUS_COMPRESSED_UNORDERED | CHUNK_STATUS_COMPRESSED_PARTIAL))
-		ereport(LOG,
+		ereport(DEBUG1,
 				(errmsg("cleared chunk status for recompression: \"%s.%s\"",
 						NameStr(uncompressed_chunk->fd.schema_name),
 						NameStr(uncompressed_chunk->fd.table_name))));
 
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("acquiring locks for recompression: \"%s.%s\"",
 					NameStr(uncompressed_chunk->fd.schema_name),
 					NameStr(uncompressed_chunk->fd.table_name))));
@@ -1279,7 +1279,7 @@ recompress_chunk_segmentwise_impl(Chunk *uncompressed_chunk)
 
 	/* Index scan */
 	Relation index_rel = index_open(row_compressor.index_oid, ExclusiveLock);
-	ereport(LOG,
+	ereport(DEBUG1,
 			(errmsg("locks acquired for recompression: \"%s.%s\"",
 					NameStr(uncompressed_chunk->fd.schema_name),
 					NameStr(uncompressed_chunk->fd.table_name))));

diff --git a/tsl/src/compression/compression.c b/tsl/src/compression/compression.c
@@ -442,18 +442,7 @@ compress_chunk(Oid in_table, Oid out_table, int insert_options)
 	{
 		int64 nrows_processed = 0;
 
-		/*
-		 * even though we log the information below, this debug info
-		 * is still used for INFO messages to clients and our tests.
-		 */
-		if (ts_guc_debug_compression_path_info)
-		{
-			elog(INFO,
-				 "compress_chunk_indexscan_start matched index \"%s\"",
-				 get_rel_name(matched_index_rel->rd_id));
-		}
-
-		elog(LOG,
+		elog(ts_guc_debug_compression_path_info ? INFO : DEBUG1,
 			 "using index \"%s\" to scan rows for compression",
 			 get_rel_name(matched_index_rel->rd_id));
 
@@ -465,7 +454,7 @@ compress_chunk(Oid in_table, Oid out_table, int insert_options)
 		{
 			row_compressor_process_ordered_slot(&row_compressor, slot, mycid);
 			if ((++nrows_processed % report_reltuples) == 0)
-				elog(LOG,
+				elog(DEBUG2,
 					 "compressed " INT64_FORMAT " rows from \"%s\"",
 					 nrows_processed,
 					 RelationGetRelationName(in_rel));
@@ -474,7 +463,7 @@ compress_chunk(Oid in_table, Oid out_table, int insert_options)
 		if (row_compressor.rows_compressed_into_current_value > 0)
 			row_compressor_flush(&row_compressor, mycid, true);
 
-		elog(LOG,
+		elog(DEBUG1,
 			 "finished compressing " INT64_FORMAT " rows from \"%s\"",
 			 nrows_processed,
 			 RelationGetRelationName(in_rel));
@@ -485,16 +474,7 @@ compress_chunk(Oid in_table, Oid out_table, int insert_options)
 	}
 	else
 	{
-		/*
-		 * even though we log the information below, this debug info
-		 * is still used for INFO messages to clients and our tests.
-		 */
-		if (ts_guc_debug_compression_path_info)
-		{
-			elog(INFO, "compress_chunk_tuplesort_start");
-		}
-
-		elog(LOG,
+		elog(ts_guc_debug_compression_path_info ? INFO : DEBUG1,
 			 "using tuplesort to scan rows from \"%s\" for compression",
 			 RelationGetRelationName(in_rel));
 
@@ -862,15 +842,15 @@ row_compressor_append_sorted_rows(RowCompressor *row_compressor, Tuplesortstate
 	{
 		row_compressor_process_ordered_slot(row_compressor, slot, mycid);
 		if ((++nrows_processed % report_reltuples) == 0)
-			elog(LOG,
+			elog(DEBUG2,
 				 "compressed " INT64_FORMAT " rows from \"%s\"",
 				 nrows_processed,
 				 RelationGetRelationName(in_rel));
 	}
 
 	if (row_compressor->rows_compressed_into_current_value > 0)
 		row_compressor_flush(row_compressor, mycid, true);
-	elog(LOG,
+	elog(DEBUG1,
 		 "finished compressing " INT64_FORMAT " rows from \"%s\"",
 		 nrows_processed,
 		 RelationGetRelationName(in_rel));
@@ -1330,13 +1310,13 @@ decompress_chunk(Oid in_table, Oid out_table)
 		row_decompressor_decompress_row_to_table(&decompressor);
 
 		if ((++nrows_processed % report_reltuples) == 0)
-			elog(LOG,
+			elog(DEBUG2,
 				 "decompressed " INT64_FORMAT " rows from \"%s\"",
 				 nrows_processed,
 				 RelationGetRelationName(in_rel));
 	}
 
-	elog(LOG,
+	elog(DEBUG1,
 		 "finished decompressing " INT64_FORMAT " rows from \"%s\"",
 		 nrows_processed,
 		 RelationGetRelationName(in_rel));

diff --git a/tsl/test/expected/compression_bgw.out b/tsl/test/expected/compression_bgw.out
@@ -351,11 +351,6 @@ SELECT alter_job(id,config:=jsonb_set(config,'{verbose_log}', 'true'))
 set client_min_messages TO LOG;
 CALL run_job(:job_id);
 LOG:  statement: CALL run_job(1004);
-LOG:  acquiring locks for compressing "_timescaledb_internal._hyper_11_40_chunk"
-LOG:  locks acquired for compressing "_timescaledb_internal._hyper_11_40_chunk"
-LOG:  new compressed chunk "_timescaledb_internal.compress_hyper_13_61_chunk" created
-LOG:  using tuplesort to scan rows from "_hyper_11_40_chunk" for compression
-LOG:  finished compressing 144 rows from "_hyper_11_40_chunk"
 LOG:  job 1004 completed processing chunk _timescaledb_internal._hyper_11_40_chunk
 set client_min_messages TO NOTICE;
 LOG:  statement: set client_min_messages TO NOTICE;

diff --git a/tsl/test/expected/compression_conflicts.out b/tsl/test/expected/compression_conflicts.out
@@ -37,7 +37,7 @@ INSERT INTO comp_conflicts_1 VALUES
 ROLLBACK;
 SELECT compress_chunk(c) AS "CHUNK" FROM show_chunks('comp_conflicts_1') c
 \gset
-INFO:  compress_chunk_tuplesort_start
+INFO:  using tuplesort to scan rows from "_hyper_1_1_chunk" for compression
 -- after compression no data should be in uncompressed chunk
 SELECT count(*) FROM ONLY :CHUNK;
  count 
@@ -123,7 +123,7 @@ INSERT INTO comp_conflicts_2 VALUES ('2020-01-01','d1',0.1);
 INSERT INTO comp_conflicts_2 VALUES ('2020-01-01','d2',0.2);
 SELECT compress_chunk(c) AS "CHUNK" FROM show_chunks('comp_conflicts_2') c
 \gset
-INFO:  compress_chunk_tuplesort_start
+INFO:  using tuplesort to scan rows from "_hyper_3_3_chunk" for compression
 -- after compression no data should be in uncompressed chunk
 SELECT count(*) FROM ONLY :CHUNK;
  count 
@@ -212,7 +212,7 @@ INSERT INTO comp_conflicts_3 VALUES ('2020-01-01','d2', 'label', 0.2);
 INSERT INTO comp_conflicts_3 VALUES ('2020-01-01',NULL, 'label', 0.3);
 SELECT compress_chunk(c) AS "CHUNK" FROM show_chunks('comp_conflicts_3') c
 \gset
-INFO:  compress_chunk_tuplesort_start
+INFO:  using tuplesort to scan rows from "_hyper_5_5_chunk" for compression
 -- after compression no data should be in uncompressed chunk
 SELECT count(*) FROM ONLY :CHUNK;
  count 
@@ -465,7 +465,7 @@ INSERT INTO comp_conflicts_4 VALUES ('2020-01-01','d2',0.2);
 INSERT INTO comp_conflicts_4 VALUES ('2020-01-01',NULL,0.3);
 SELECT compress_chunk(c) AS "CHUNK" FROM show_chunks('comp_conflicts_4') c
 \gset
-INFO:  compress_chunk_tuplesort_start
+INFO:  using tuplesort to scan rows from "_hyper_7_7_chunk" for compression
 -- after compression no data should be in uncompressed chunk
 SELECT count(*) FROM ONLY :CHUNK;
  count 
@@ -611,9 +611,9 @@ ALTER TABLE compressed_ht SET (
 );
 NOTICE:  default order by for hypertable "compressed_ht" is set to ""time" DESC"
 SELECT COMPRESS_CHUNK(SHOW_CHUNKS('compressed_ht'));
-INFO:  compress_chunk_tuplesort_start
-INFO:  compress_chunk_tuplesort_start
-INFO:  compress_chunk_tuplesort_start
+INFO:  using tuplesort to scan rows from "_hyper_9_9_chunk" for compression
+INFO:  using tuplesort to scan rows from "_hyper_9_10_chunk" for compression
+INFO:  using tuplesort to scan rows from "_hyper_9_11_chunk" for compression
              compress_chunk              
 -----------------------------------------
  _timescaledb_internal._hyper_9_9_chunk