From 433840d87974be15efe66bc7c39b151decbd7e4e Mon Sep 17 00:00:00 2001 From: Slach Date: Mon, 7 Oct 2024 12:07:38 +0500 Subject: [PATCH] debug TestLongListRemote --- .github/workflows/build.yaml | 4 ++-- pkg/backup/list.go | 12 +++++++++++- pkg/storage/general.go | 16 ++++++++++++++++ 3 files changed, 29 insertions(+), 3 deletions(-) diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index f610acc9..cc3606e7 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -269,8 +269,8 @@ jobs: GOROOT: ${{ env.GOROOT_1_22_X64 }} CLICKHOUSE_VERSION: ${{ matrix.clickhouse }} # options for advanced debug CI/CD - # RUN_TESTS: "TestLongListRemote" - # LOG_LEVEL: "debug" + RUN_TESTS: "TestLongListRemote" + LOG_LEVEL: "debug" # TEST_LOG_LEVEL: "debug" # GCS_DEBUG: "true" # SFTP_DEBUG: "true" diff --git a/pkg/backup/list.go b/pkg/backup/list.go index 8f148f3a..9646512c 100644 --- a/pkg/backup/list.go +++ b/pkg/backup/list.go @@ -12,6 +12,7 @@ import ( "sort" "strings" "text/tabwriter" + "time" "github.com/Altinity/clickhouse-backup/v2/pkg/clickhouse" "github.com/Altinity/clickhouse-backup/v2/pkg/custom" @@ -305,9 +306,11 @@ func (b *Backuper) PrintAllBackups(ctx context.Context, format string) error { // PrintRemoteBackups - print all backups stored on remote storage func (b *Backuper) PrintRemoteBackups(ctx context.Context, format string) error { if !b.ch.IsOpen { + chConnectStart := time.Now() if err := b.ch.Connect(); err != nil { return fmt.Errorf("can't connect to clickhouse: %v", err) } + log.Debug().TimeDiff("chConnectStart", time.Now(), chConnectStart).Send() defer b.ch.Close() } w := tabwriter.NewWriter(os.Stdout, 0, 0, 3, ' ', tabwriter.DiscardEmptyColumns) @@ -316,11 +319,16 @@ func (b *Backuper) PrintRemoteBackups(ctx context.Context, format string) error log.Error().Msgf("can't flush tabular writer error: %v", err) } }() + getRemoteBackupsStart := time.Now() backupList, err := b.GetRemoteBackups(ctx, true) if err != nil { return err } - return printBackupsRemote(w, backupList, format) + log.Debug().TimeDiff("b.GetRemoteBackups", time.Now(), getRemoteBackupsStart).Send() + printBackupsRemoteStart := time.Now() + err = printBackupsRemote(w, backupList, format) + log.Debug().TimeDiff("printBackupsRemote", time.Now(), printBackupsRemoteStart).Send() + return err } func (b *Backuper) getLocalBackup(ctx context.Context, backupName string, disks []clickhouse.Disk) (*LocalBackup, []clickhouse.Disk, error) { @@ -358,9 +366,11 @@ func (b *Backuper) GetRemoteBackups(ctx context.Context, parseMetadata bool) ([] if err != nil { return []storage.Backup{}, err } + bdConnectStart := time.Now() if err := bd.Connect(ctx); err != nil { return []storage.Backup{}, err } + log.Debug().TimeDiff("bd.Connect", time.Now(), bdConnectStart).Send() defer func() { if err := bd.Close(ctx); err != nil { log.Warn().Msgf("can't close BackupDestination error: %v", err) diff --git a/pkg/storage/general.go b/pkg/storage/general.go index 532825fa..415b4915 100644 --- a/pkg/storage/general.go +++ b/pkg/storage/general.go @@ -75,6 +75,11 @@ func (bd *BackupDestination) RemoveBackupRemote(ctx context.Context, backup Back } func (bd *BackupDestination) loadMetadataCache(ctx context.Context) (map[string]Backup, error) { + loadMetadataCacheStart := time.Now() + defer func() { + log.Debug().TimeDiff("bd.loadMetadataCache", time.Now(), loadMetadataCacheStart).Send() + }() + listCacheFile := path.Join(os.TempDir(), fmt.Sprintf(".clickhouse-backup-metadata.cache.%s", bd.Kind())) listCache := map[string]Backup{} if _, err := os.Stat(listCacheFile); os.IsNotExist(err) { @@ -158,6 +163,10 @@ func (bd *BackupDestination) saveMetadataCache(ctx context.Context, listCache ma } func (bd *BackupDestination) BackupList(ctx context.Context, parseMetadata bool, parseMetadataOnly string) ([]Backup, error) { + backupListStart := time.Now() + defer func() { + log.Debug().TimeDiff("bd.BackupList", time.Now(), backupListStart).Send() + }() result := make([]Backup, 0) metadataCacheLock.Lock() defer metadataCacheLock.Unlock() @@ -169,12 +178,15 @@ func (bd *BackupDestination) BackupList(ctx context.Context, parseMetadata bool, parseMetadata = true } cacheMiss := false + cacheMissCount := 0 + walkStart := time.Now() err = bd.Walk(ctx, "/", false, func(ctx context.Context, o RemoteFile) error { backupName := strings.Trim(o.Name(), "/") if !parseMetadata || (parseMetadataOnly != "" && parseMetadataOnly != backupName) { if cachedMetadata, isCached := listCache[backupName]; isCached { result = append(result, cachedMetadata) } else { + cacheMissCount++ result = append(result, Backup{ BackupMetadata: metadata.BackupMetadata{ BackupName: backupName, @@ -187,6 +199,7 @@ func (bd *BackupDestination) BackupList(ctx context.Context, parseMetadata bool, result = append(result, cachedMetadata) return nil } + cacheMissCount++ mf, err := bd.StatFile(ctx, path.Join(o.Name(), "metadata.json")) if err != nil { brokenBackup := Backup{ @@ -247,6 +260,8 @@ func (bd *BackupDestination) BackupList(ctx context.Context, parseMetadata bool, if err != nil { log.Warn().Msgf("BackupList bd.Walk return error: %v", err) } + log.Debug().TimeDiff("bd.Walk", time.Now(), walkStart).Int("cacheMissCount", cacheMissCount).Send() + sortStart := time.Now() // sort by name for the same not parsed metadata.json sort.SliceStable(result, func(i, j int) bool { return result[i].BackupName < result[j].BackupName @@ -254,6 +269,7 @@ func (bd *BackupDestination) BackupList(ctx context.Context, parseMetadata bool, sort.SliceStable(result, func(i, j int) bool { return result[i].UploadDate.Before(result[j].UploadDate) }) + log.Debug().TimeDiff("sort.SliceStable", time.Now(), sortStart).Send() if cacheMiss || len(result) < len(listCache) { if err = bd.saveMetadataCache(ctx, listCache, result); err != nil { return nil, fmt.Errorf("bd.saveMetadataCache return error: %v", err)