diff --git a/app/victoria-metrics/main.go b/app/victoria-metrics/main.go index 78e7458905..9a8e067b59 100644 --- a/app/victoria-metrics/main.go +++ b/app/victoria-metrics/main.go @@ -28,7 +28,7 @@ func main() { vminsert.Init() go httpserver.Serve(*httpListenAddr, requestHandler) - logger.Infof("started VictoriaMetrics in %s", time.Since(startTime)) + logger.Infof("started VictoriaMetrics in %.3f seconds", time.Since(startTime).Seconds()) sig := procutil.WaitForSigterm() logger.Infof("received signal %s", sig) @@ -39,14 +39,14 @@ func main() { logger.Fatalf("cannot stop the webservice: %s", err) } vminsert.Stop() - logger.Infof("successfully shut down the webservice in %s", time.Since(startTime)) + logger.Infof("successfully shut down the webservice in %.3f seconds", time.Since(startTime).Seconds()) vmstorage.Stop() vmselect.Stop() fs.MustStopDirRemover() - logger.Infof("the VictoriaMetrics has been stopped in %s", time.Since(startTime)) + logger.Infof("the VictoriaMetrics has been stopped in %.3f seconds", time.Since(startTime).Seconds()) } func requestHandler(w http.ResponseWriter, r *http.Request) bool { diff --git a/app/vmselect/promql/exec.go b/app/vmselect/promql/exec.go index 1c248d7994..83153ba77d 100644 --- a/app/vmselect/promql/exec.go +++ b/app/vmselect/promql/exec.go @@ -26,8 +26,8 @@ func Exec(ec *EvalConfig, q string, isFirstPointOnly bool) ([]netstorage.Result, defer func() { d := time.Since(startTime) if d >= *logSlowQueryDuration { - logger.Infof("slow query according to -search.logSlowQueryDuration=%s: duration=%s, start=%d, end=%d, step=%d, query=%q", - *logSlowQueryDuration, d, ec.Start/1000, ec.End/1000, ec.Step/1000, q) + logger.Infof("slow query according to -search.logSlowQueryDuration=%s: duration=%.3f seconds, start=%d, end=%d, step=%d, query=%q", + *logSlowQueryDuration, d.Seconds(), ec.Start/1000, ec.End/1000, ec.Step/1000, q) slowQueries.Inc() } }() diff --git a/app/vmselect/promql/rollup_result_cache.go b/app/vmselect/promql/rollup_result_cache.go index abe54565b9..8a807a8020 100644 --- a/app/vmselect/promql/rollup_result_cache.go +++ b/app/vmselect/promql/rollup_result_cache.go @@ -74,8 +74,8 @@ func InitRollupResultCache(cachePath string) { return stats } if len(rollupResultCachePath) > 0 { - logger.Infof("loaded rollupResult cache from %q in %s; entriesCount: %d, sizeBytes: %d", - rollupResultCachePath, time.Since(startTime), fcs().EntriesCount, fcs().BytesSize) + logger.Infof("loaded rollupResult cache from %q in %.3f seconds; entriesCount: %d, sizeBytes: %d", + rollupResultCachePath, time.Since(startTime).Seconds(), fcs().EntriesCount, fcs().BytesSize) } metrics.NewGauge(`vm_cache_entries{type="promql/rollupResult"}`, func() float64 { @@ -113,8 +113,8 @@ func StopRollupResultCache() { rollupResultCacheV.c.UpdateStats(&fcs) rollupResultCacheV.c.Stop() rollupResultCacheV.c = nil - logger.Infof("saved rollupResult cache to %q in %s; entriesCount: %d, sizeBytes: %d", - rollupResultCachePath, time.Since(startTime), fcs.EntriesCount, fcs.BytesSize) + logger.Infof("saved rollupResult cache to %q in %.3f seconds; entriesCount: %d, sizeBytes: %d", + rollupResultCachePath, time.Since(startTime).Seconds(), fcs.EntriesCount, fcs.BytesSize) } type rollupResultCache struct { diff --git a/app/vmstorage/main.go b/app/vmstorage/main.go index d00a0ef67f..f25648ad57 100644 --- a/app/vmstorage/main.go +++ b/app/vmstorage/main.go @@ -62,8 +62,8 @@ func InitWithoutMetrics() { blocksCount := tm.SmallBlocksCount + tm.BigBlocksCount rowsCount := tm.SmallRowsCount + tm.BigRowsCount sizeBytes := tm.SmallSizeBytes + tm.BigSizeBytes - logger.Infof("successfully opened storage %q in %s; partsCount: %d; blocksCount: %d; rowsCount: %d; sizeBytes: %d", - *DataPath, time.Since(startTime), partsCount, blocksCount, rowsCount, sizeBytes) + logger.Infof("successfully opened storage %q in %.3f seconds; partsCount: %d; blocksCount: %d; rowsCount: %d; sizeBytes: %d", + *DataPath, time.Since(startTime).Seconds(), partsCount, blocksCount, rowsCount, sizeBytes) } // Storage is a storage. @@ -133,7 +133,7 @@ func Stop() { startTime := time.Now() WG.WaitAndBlock() Storage.MustClose() - logger.Infof("successfully closed the storage in %s", time.Since(startTime)) + logger.Infof("successfully closed the storage in %.3f seconds", time.Since(startTime).Seconds()) logger.Infof("the storage has been stopped") } diff --git a/lib/backup/actions/backup.go b/lib/backup/actions/backup.go index bbc8df4f69..6661af9c12 100644 --- a/lib/backup/actions/backup.go +++ b/lib/backup/actions/backup.go @@ -166,8 +166,8 @@ func runBackup(src *fslocal.FS, dst common.RemoteFS, origin common.OriginFS, con } } - logger.Infof("backed up %d bytes in %s; deleted %d bytes; server-side copied %d bytes; uploaded %d bytes", - backupSize, time.Since(startTime), deleteSize, copySize, uploadSize) + logger.Infof("backed up %d bytes in %.3f seconds; deleted %d bytes; server-side copied %d bytes; uploaded %d bytes", + backupSize, time.Since(startTime).Seconds(), deleteSize, copySize, uploadSize) return nil } diff --git a/lib/backup/actions/restore.go b/lib/backup/actions/restore.go index 5994dea813..f681e876ca 100644 --- a/lib/backup/actions/restore.go +++ b/lib/backup/actions/restore.go @@ -182,7 +182,8 @@ func (r *Restore) Run() error { } } - logger.Infof("restored %d bytes from backup in %s; deleted %d bytes; downloaded %d bytes", backupSize, time.Since(startTime), deleteSize, downloadSize) + logger.Infof("restored %d bytes from backup in %.3f seconds; deleted %d bytes; downloaded %d bytes", + backupSize, time.Since(startTime).Seconds(), deleteSize, downloadSize) return nil } diff --git a/lib/mergeset/table.go b/lib/mergeset/table.go index f966d2cac0..7a0c0df460 100644 --- a/lib/mergeset/table.go +++ b/lib/mergeset/table.go @@ -187,8 +187,8 @@ func OpenTable(path string, flushCallback func(), prepareBlock PrepareBlockCallb var m TableMetrics tb.UpdateMetrics(&m) - logger.Infof("table %q has been opened in %s; partsCount: %d; blocksCount: %d, itemsCount: %d; sizeBytes: %d", - path, time.Since(startTime), m.PartsCount, m.BlocksCount, m.ItemsCount, m.SizeBytes) + logger.Infof("table %q has been opened in %.3f seconds; partsCount: %d; blocksCount: %d, itemsCount: %d; sizeBytes: %d", + path, time.Since(startTime).Seconds(), m.PartsCount, m.BlocksCount, m.ItemsCount, m.SizeBytes) tb.convertersWG.Add(1) go func() { @@ -206,17 +206,17 @@ func (tb *Table) MustClose() { logger.Infof("waiting for raw items flusher to stop on %q...", tb.path) startTime := time.Now() tb.rawItemsFlusherWG.Wait() - logger.Infof("raw items flusher stopped in %s on %q", time.Since(startTime), tb.path) + logger.Infof("raw items flusher stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), tb.path) logger.Infof("waiting for converters to stop on %q...", tb.path) startTime = time.Now() tb.convertersWG.Wait() - logger.Infof("converters stopped in %s on %q", time.Since(startTime), tb.path) + logger.Infof("converters stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), tb.path) logger.Infof("waiting for part mergers to stop on %q...", tb.path) startTime = time.Now() tb.partMergersWG.Wait() - logger.Infof("part mergers stopped in %s on %q", time.Since(startTime), tb.path) + logger.Infof("part mergers stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), tb.path) logger.Infof("flushing inmemory parts to files on %q...", tb.path) startTime = time.Now() @@ -242,7 +242,7 @@ func (tb *Table) MustClose() { if err := tb.mergePartsOptimal(pws, nil); err != nil { logger.Panicf("FATAL: cannot flush inmemory parts to files in %q: %s", tb.path, err) } - logger.Infof("%d inmemory parts have been flushed to files in %s on %q", len(pws), time.Since(startTime), tb.path) + logger.Infof("%d inmemory parts have been flushed to files in %.3f seconds on %q", len(pws), time.Since(startTime).Seconds(), tb.path) // Remove references to parts from the tb, so they may be eventually closed // after all the searches are done. @@ -447,7 +447,7 @@ func (tb *Table) convertToV1280() { logger.Errorf("failed round 1 of background conversion of %q to v1.28.0 format: %s", tb.path, err) return } - logger.Infof("finished round 1 of background conversion of %q to v1.28.0 format in %s", tb.path, time.Since(startTime)) + logger.Infof("finished round 1 of background conversion of %q to v1.28.0 format in %.3f seconds", tb.path, time.Since(startTime).Seconds()) // The second round is needed in order to merge small blocks // with tag->metricIDs rows left after the first round. @@ -460,7 +460,7 @@ func (tb *Table) convertToV1280() { return } } - logger.Infof("finished round 2 of background conversion of %q to v1.28.0 format in %s", tb.path, time.Since(startTime)) + logger.Infof("finished round 2 of background conversion of %q to v1.28.0 format in %.3f seconds", tb.path, time.Since(startTime).Seconds()) } if err := fs.WriteFileAtomically(flagFilePath, []byte("ok")); err != nil { @@ -853,7 +853,8 @@ func (tb *Table) mergeParts(pws []*partWrapper, stopCh <-chan struct{}, isOuterP d := time.Since(startTime) if d > 10*time.Second { - logger.Infof("merged %d items in %s at %d items/sec to %q; sizeBytes: %d", outItemsCount, d, int(float64(outItemsCount)/d.Seconds()), dstPartPath, newPSize) + logger.Infof("merged %d items in %.3f seconds at %d items/sec to %q; sizeBytes: %d", + outItemsCount, d.Seconds(), int(float64(outItemsCount)/d.Seconds()), dstPartPath, newPSize) } return nil @@ -1057,7 +1058,7 @@ func (tb *Table) CreateSnapshotAt(dstDir string) error { parentDir := filepath.Dir(dstDir) fs.MustSyncPath(parentDir) - logger.Infof("created Table snapshot of %q at %q in %s", srcDir, dstDir, time.Since(startTime)) + logger.Infof("created Table snapshot of %q at %q in %.3f seconds", srcDir, dstDir, time.Since(startTime).Seconds()) return nil } diff --git a/lib/storage/partition.go b/lib/storage/partition.go index aa50b0f35c..feaad32bec 100644 --- a/lib/storage/partition.go +++ b/lib/storage/partition.go @@ -613,22 +613,22 @@ func (pt *partition) MustClose() { logger.Infof("waiting for inmemory parts flusher to stop on %q...", pt.smallPartsPath) startTime := time.Now() pt.inmemoryPartsFlusherWG.Wait() - logger.Infof("inmemory parts flusher stopped in %s on %q", time.Since(startTime), pt.smallPartsPath) + logger.Infof("inmemory parts flusher stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), pt.smallPartsPath) logger.Infof("waiting for raw rows flusher to stop on %q...", pt.smallPartsPath) startTime = time.Now() pt.rawRowsFlusherWG.Wait() - logger.Infof("raw rows flusher stopped in %s on %q", time.Since(startTime), pt.smallPartsPath) + logger.Infof("raw rows flusher stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), pt.smallPartsPath) logger.Infof("waiting for small part mergers to stop on %q...", pt.smallPartsPath) startTime = time.Now() pt.smallPartsMergerWG.Wait() - logger.Infof("small part mergers stopped in %s on %q", time.Since(startTime), pt.smallPartsPath) + logger.Infof("small part mergers stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), pt.smallPartsPath) logger.Infof("waiting for big part mergers to stop on %q...", pt.bigPartsPath) startTime = time.Now() pt.bigPartsMergerWG.Wait() - logger.Infof("big part mergers stopped in %s on %q", time.Since(startTime), pt.bigPartsPath) + logger.Infof("big part mergers stopped in %.3f seconds on %q", time.Since(startTime).Seconds(), pt.bigPartsPath) logger.Infof("flushing inmemory parts to files on %q...", pt.smallPartsPath) startTime = time.Now() @@ -654,7 +654,7 @@ func (pt *partition) MustClose() { if err := pt.mergePartsOptimal(pws); err != nil { logger.Panicf("FATAL: cannot flush %d inmemory parts to files on %q: %s", len(pws), pt.smallPartsPath, err) } - logger.Infof("%d inmemory parts have been flushed to files in %s on %q", len(pws), time.Since(startTime), pt.smallPartsPath) + logger.Infof("%d inmemory parts have been flushed to files in %.3f seconds on %q", len(pws), time.Since(startTime).Seconds(), pt.smallPartsPath) // Remove references to smallParts from the pt, so they may be eventually closed // after all the searches are done. @@ -1167,7 +1167,8 @@ func (pt *partition) mergeParts(pws []*partWrapper, stopCh <-chan struct{}) erro d := time.Since(startTime) if d > 10*time.Second { - logger.Infof("merged %d rows in %s at %d rows/sec to %q; sizeBytes: %d", outRowsCount, d, int(float64(outRowsCount)/d.Seconds()), dstPartPath, newPSize) + logger.Infof("merged %d rows in %.3f seconds at %d rows/sec to %q; sizeBytes: %d", + outRowsCount, d.Seconds(), int(float64(outRowsCount)/d.Seconds()), dstPartPath, newPSize) } return nil @@ -1359,8 +1360,7 @@ func openParts(pathPrefix1, pathPrefix2, path string) ([]*partWrapper, error) { mustCloseParts(pws) return nil, fmt.Errorf("cannot open part %q: %s", partPath, err) } - d := time.Since(startTime) - logger.Infof("opened part %q in %s", partPath, d) + logger.Infof("opened part %q in %.3f seconds", partPath, time.Since(startTime).Seconds()) pw := &partWrapper{ p: p, @@ -1407,7 +1407,8 @@ func (pt *partition) CreateSnapshotAt(smallPath, bigPath string) error { return fmt.Errorf("cannot create snapshot for %q: %s", pt.bigPartsPath, err) } - logger.Infof("created partition snapshot of %q and %q at %q and %q in %s", pt.smallPartsPath, pt.bigPartsPath, smallPath, bigPath, time.Since(startTime)) + logger.Infof("created partition snapshot of %q and %q at %q and %q in %.3f seconds", + pt.smallPartsPath, pt.bigPartsPath, smallPath, bigPath, time.Since(startTime).Seconds()) return nil } diff --git a/lib/storage/storage.go b/lib/storage/storage.go index f5bfe1a312..95d7958465 100644 --- a/lib/storage/storage.go +++ b/lib/storage/storage.go @@ -216,7 +216,7 @@ func (s *Storage) CreateSnapshot() (string, error) { fs.MustSyncPath(dstDir) fs.MustSyncPath(srcDir + "/snapshots") - logger.Infof("created Storage snapshot for %q at %q in %s", srcDir, dstDir, time.Since(startTime)) + logger.Infof("created Storage snapshot for %q at %q in %.3f seconds", srcDir, dstDir, time.Since(startTime).Seconds()) return snapshotName, nil } @@ -261,7 +261,7 @@ func (s *Storage) DeleteSnapshot(snapshotName string) error { fs.MustRemoveAll(idbPath) fs.MustRemoveAll(snapshotPath) - logger.Infof("deleted snapshot %q in %s", snapshotPath, time.Since(startTime)) + logger.Infof("deleted snapshot %q in %.3f seconds", snapshotPath, time.Since(startTime).Seconds()) return nil } @@ -529,7 +529,7 @@ func (s *Storage) mustLoadHourMetricIDs(hour uint64, name string) *hourMetricIDs m.Add(metricID) } - logger.Infof("loaded %s from %q in %s; entriesCount: %d; sizeBytes: %d", name, path, time.Since(startTime), hmLen, srcOrigLen) + logger.Infof("loaded %s from %q in %.3f seconds; entriesCount: %d; sizeBytes: %d", name, path, time.Since(startTime).Seconds(), hmLen, srcOrigLen) return &hourMetricIDs{ m: m, hour: hourLoaded, @@ -563,7 +563,7 @@ func (s *Storage) mustSaveHourMetricIDs(hm *hourMetricIDs, name string) { if err := ioutil.WriteFile(path, dst, 0644); err != nil { logger.Panicf("FATAL: cannot write %d bytes to %q: %s", len(dst), path, err) } - logger.Infof("saved %s to %q in %s; entriesCount: %d; sizeBytes: %d", name, path, time.Since(startTime), hm.m.Len(), len(dst)) + logger.Infof("saved %s to %q in %.3f seconds; entriesCount: %d; sizeBytes: %d", name, path, time.Since(startTime).Seconds(), hm.m.Len(), len(dst)) } func (s *Storage) mustLoadCache(info, name string, sizeBytes int) *workingsetcache.Cache { @@ -573,8 +573,8 @@ func (s *Storage) mustLoadCache(info, name string, sizeBytes int) *workingsetcac c := workingsetcache.Load(path, sizeBytes, time.Hour) var cs fastcache.Stats c.UpdateStats(&cs) - logger.Infof("loaded %s cache from %q in %s; entriesCount: %d; sizeBytes: %d", - info, path, time.Since(startTime), cs.EntriesCount, cs.BytesSize) + logger.Infof("loaded %s cache from %q in %.3f seconds; entriesCount: %d; sizeBytes: %d", + info, path, time.Since(startTime).Seconds(), cs.EntriesCount, cs.BytesSize) return c } @@ -588,8 +588,8 @@ func (s *Storage) mustSaveAndStopCache(c *workingsetcache.Cache, info, name stri var cs fastcache.Stats c.UpdateStats(&cs) c.Stop() - logger.Infof("saved %s cache to %q in %s; entriesCount: %d; sizeBytes: %d", - info, path, time.Since(startTime), cs.EntriesCount, cs.BytesSize) + logger.Infof("saved %s cache to %q in %.3f seconds; entriesCount: %d; sizeBytes: %d", + info, path, time.Since(startTime).Seconds(), cs.EntriesCount, cs.BytesSize) } func nextRetentionDuration(retentionMonths int) time.Duration { diff --git a/lib/storage/table.go b/lib/storage/table.go index 3746a05473..698b4569d6 100644 --- a/lib/storage/table.go +++ b/lib/storage/table.go @@ -170,7 +170,7 @@ func (tb *table) CreateSnapshot(snapshotName string) (string, string, error) { fs.MustSyncPath(filepath.Dir(dstSmallDir)) fs.MustSyncPath(filepath.Dir(dstBigDir)) - logger.Infof("created table snapshot for %q at (%q, %q) in %s", tb.path, dstSmallDir, dstBigDir, time.Since(startTime)) + logger.Infof("created table snapshot for %q at (%q, %q) in %.3f seconds", tb.path, dstSmallDir, dstBigDir, time.Since(startTime).Seconds()) return dstSmallDir, dstBigDir, nil }