From 31282d67b79e96a2a1c486be86c1eee4a5b6e88d Mon Sep 17 00:00:00 2001 From: Lukasz Mierzwa Date: Fri, 22 Aug 2025 16:03:32 +0100 Subject: [PATCH] Log when GC / block write starts Right now Prometheus only logs when these operations are completed. It's a bit surprising to see suddenly a message saying "I was busy doing X for the past N minutes" so let's add a message when the operation starts, so it's easier to understand what Prometheus was doing at any point in time when reading logs. Signed-off-by: Lukasz Mierzwa --- tsdb/agent/db.go | 1 + tsdb/compact.go | 3 ++- tsdb/db.go | 1 + tsdb/head.go | 1 + 4 files changed, 5 insertions(+), 1 deletion(-) diff --git a/tsdb/agent/db.go b/tsdb/agent/db.go index 4e53b6168b..1c8eaa886f 100644 --- a/tsdb/agent/db.go +++ b/tsdb/agent/db.go @@ -648,6 +648,7 @@ func (db *DB) keepSeriesInWALCheckpointFn(last int) func(id chunks.HeadSeriesRef } func (db *DB) truncate(mint int64) error { + db.logger.Info("series GC started") db.mtx.RLock() defer db.mtx.RUnlock() diff --git a/tsdb/compact.go b/tsdb/compact.go index 0641b75720..e499953934 100644 --- a/tsdb/compact.go +++ b/tsdb/compact.go @@ -562,6 +562,7 @@ func (c *LeveledCompactor) Write(dest string, b BlockReader, mint, maxt int64, b start := time.Now() uid := ulid.MustNew(ulid.Now(), rand.Reader) + c.logger.Info("write block started", "mint", mint, "maxt", maxt, "ulid", uid) meta := &BlockMeta{ ULID: uid, @@ -596,7 +597,7 @@ func (c *LeveledCompactor) Write(dest string, b BlockReader, mint, maxt int64, b } c.logger.Info( - "write block", + "write block completed", "mint", meta.MinTime, "maxt", meta.MaxTime, "ulid", meta.ULID, diff --git a/tsdb/db.go b/tsdb/db.go index 093ec5ab27..b0de45775d 100644 --- a/tsdb/db.go +++ b/tsdb/db.go @@ -1420,6 +1420,7 @@ func (db *DB) compactOOOHead(ctx context.Context) error { // Each ULID in the result corresponds to a block in a unique time range. // The db.cmtx mutex should be held before calling this method. func (db *DB) compactOOO(dest string, oooHead *OOOCompactionHead) (_ []ulid.ULID, err error) { + db.logger.Info("out-of-order compaction started") start := time.Now() blockSize := oooHead.ChunkRange() diff --git a/tsdb/head.go b/tsdb/head.go index cd0f771f96..aa69138954 100644 --- a/tsdb/head.go +++ b/tsdb/head.go @@ -1416,6 +1416,7 @@ func (h *Head) truncateOOO(lastWBLFile int, newMinOOOMmapRef chunks.ChunkDiskMap // truncateSeriesAndChunkDiskMapper is a helper function for truncateMemory and truncateOOO. // It runs GC on the Head and truncates the ChunkDiskMapper accordingly. func (h *Head) truncateSeriesAndChunkDiskMapper(caller string) error { + h.logger.Info("Head GC started", "caller", caller) start := time.Now() headMaxt := h.MaxTime() actualMint, minOOOTime, minMmapFile := h.gc()