debug TestLongListRemote

Altinity · Oct 7, 2024 · 433840d · 433840d
1 parent b80de91
commit 433840d
Show file tree

Hide file tree

Showing 3 changed files with 29 additions and 3 deletions.
diff --git 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
@@ -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
@@ -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,13 +260,16 @@ 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
 	})
 	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)