rebuildnodes: Improve logging

2 files changed, 53 insertions, 4 deletions

diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/orphans.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/orphans.go
index 70bd128..55cf95b 100644
--- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/orphans.go
+++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/orphans.go
@@ -5,12 +5,17 @@
 package rebuildnodes
 
 import (
+	"context"
+
+	"github.com/datawire/dlib/dlog"
+
 	"git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsprim"
 	"git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfstree"
 	"git.lukeshu.com/btrfs-progs-ng/lib/btrfs/btrfsvol"
 	"git.lukeshu.com/btrfs-progs-ng/lib/btrfsprogs/btrfsinspect/rebuildnodes/graph"
 	"git.lukeshu.com/btrfs-progs-ng/lib/containers"
 	"git.lukeshu.com/btrfs-progs-ng/lib/diskio"
+	"git.lukeshu.com/btrfs-progs-ng/lib/maps"
 )
 
 func listRoots(graph graph.Graph, leaf btrfsvol.LogicalAddr) containers.Set[btrfsvol.LogicalAddr] {
@@ -49,12 +54,13 @@ func (a keyAndTree) Cmp(b keyAndTree) int {
 	return containers.NativeCmp(a.TreeID, b.TreeID)
 }
 
-func indexOrphans(fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock, graph graph.Graph) (
+func indexOrphans(ctx context.Context, fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock, graph graph.Graph) (
 	orphans containers.Set[btrfsvol.LogicalAddr],
 	leaf2orphans map[btrfsvol.LogicalAddr]containers.Set[btrfsvol.LogicalAddr],
 	key2leaf *containers.SortedMap[keyAndTree, btrfsvol.LogicalAddr],
 	err error,
 ) {
+	dlog.Info(ctx, "... counting orphans")
 	orphans = make(containers.Set[btrfsvol.LogicalAddr])
 	for node := range graph.Nodes {
 		if len(graph.EdgesTo[node]) == 0 {
@@ -64,7 +70,22 @@ func indexOrphans(fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock,
 
 	leaf2orphans = make(map[btrfsvol.LogicalAddr]containers.Set[btrfsvol.LogicalAddr])
 	visited := make(containers.Set[btrfsvol.LogicalAddr])
-	for orphan := range orphans {
+
+	lastPct, lastVisited, lastLeafs := -1, 0, 0
+	total := len(orphans)
+	done := 0
+	progress := func() {
+		pct := int(100 * float64(done) / float64(total))
+		if pct != lastPct || (len(visited) != lastVisited && len(visited)%500 == 0) || len(leaf2orphans) != lastLeafs || done == total {
+			dlog.Infof(ctx, "... crawling orphans %v%% (%v/%v); visited %d nodes, found %d leaf nodes",
+				pct, done, total, len(visited), len(leaf2orphans))
+			lastPct = pct
+			lastVisited = len(visited)
+			lastLeafs = len(leaf2orphans)
+		}
+	}
+	progress()
+	for _, orphan := range maps.SortedKeys(orphans) {
 		walk(graph, orphan, func(node btrfsvol.LogicalAddr) bool {
 			if visited.Has(node) {
 				return false
@@ -75,12 +96,26 @@ func indexOrphans(fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock,
 					leaf2orphans[node] = roots
 				}
 			}
+			progress()
 			return true
 		})
+		done++
+		progress()
 	}
 
 	key2leaf = new(containers.SortedMap[keyAndTree, btrfsvol.LogicalAddr])
-	for laddr := range leaf2orphans {
+	total = len(leaf2orphans)
+	done = 0
+	progress = func() {
+		pct := int(100 * float64(done) / float64(total))
+		if pct != lastPct || done == total {
+			dlog.Infof(ctx, "... reading leafs %v%% (%v/%v)",
+				pct, done, total)
+			lastPct = pct
+		}
+	}
+	progress()
+	for _, laddr := range maps.SortedKeys(leaf2orphans) {
 		nodeRef, err := btrfstree.ReadNode[btrfsvol.LogicalAddr](fs, sb, laddr, btrfstree.NodeExpectations{
 			LAddr: containers.Optional[btrfsvol.LogicalAddr]{OK: true, Val: laddr},
 			Level: containers.Optional[uint8]{OK: true, Val: 0},
@@ -98,6 +133,8 @@ func indexOrphans(fs diskio.File[btrfsvol.LogicalAddr], sb btrfstree.Superblock,
 				key2leaf.Store(k, laddr)
 			}
 		}
+		done++
+		progress()
 	}
 	return orphans, leaf2orphans, key2leaf, nil
 }
diff --git a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go
index be2834b..5dc4fa6 100644
--- a/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go
+++ b/lib/btrfsprogs/btrfsinspect/rebuildnodes/rebuild.go
@@ -65,7 +65,7 @@ func RebuildNodes(ctx context.Context, fs *btrfs.FS, nodeScanResults btrfsinspec
 	}
 
 	dlog.Info(ctx, "Indexing orphans...")
-	orphans, leaf2orphans, key2leaf, err := indexOrphans(fs, *sb, *scanData.nodeGraph)
+	orphans, leaf2orphans, key2leaf, err := indexOrphans(ctx, fs, *sb, *scanData.nodeGraph)
 	if err != nil {
 		return nil, err
 	}
@@ -93,6 +93,8 @@ func RebuildNodes(ctx context.Context, fs *btrfs.FS, nodeScanResults btrfsinspec
 }
 
 func (o *Rebuilder) rebuild(ctx context.Context) error {
+	passNum := 0
+	dlog.Infof(ctx, "... pass %d: scanning for implied items", passNum)
 	o.pendingAugments = make(map[btrfsprim.ObjID][]map[btrfsvol.LogicalAddr]int)
 	btrfsutil.WalkAllTrees(ctx, o.inner, btrfsutil.WalkAllTreesHandler{
 		Err: func(*btrfsutil.WalkError) {},
@@ -105,8 +107,10 @@ func (o *Rebuilder) rebuild(ctx context.Context) error {
 	})
 	for len(o.pendingAugments) > 0 {
 		// Apply the augments, keeping track of what keys are added to what tree.
+		dlog.Infof(ctx, "... pass %d: augmenting trees to add implied items", passNum)
 		newKeys := make(map[btrfsprim.ObjID][]btrfsprim.Key)
 		for _, treeID := range maps.SortedKeys(o.pendingAugments) {
+			dlog.Infof(ctx, "... ... augmenting tree %v:", treeID)
 			treeAugments := o.resolveTreeAugments(ctx, o.pendingAugments[treeID])
 			for _, nodeAddr := range maps.SortedKeys(treeAugments) {
 				added, err := o.inner.Augment(treeID, nodeAddr)
@@ -126,7 +130,9 @@ func (o *Rebuilder) rebuild(ctx context.Context) error {
 		}
 		// Clear the list of pending augments.
 		o.pendingAugments = make(map[btrfsprim.ObjID][]map[btrfsvol.LogicalAddr]int)
+		passNum++
 		// Call handleItem() for each of the added keys.
+		dlog.Infof(ctx, "... pass %d: scanning for implied items", passNum)
 		for _, treeID := range maps.SortedKeys(newKeys) {
 			for _, key := range newKeys[treeID] {
 				item, err := o.inner.TreeLookup(treeID, key)
@@ -247,6 +253,11 @@ func (o *Rebuilder) resolveTreeAugments(ctx context.Context, listsWithDistances
 			accept(item)
 		}
 	}
+
+	for i, list := range lists {
+		dlog.Infof(ctx, "... ... ... %d: %v: %v", i, list.Intersection(ret).TakeOne(), maps.SortedKeys(list))
+	}
+
 	return ret
 }
 
@@ -287,6 +298,7 @@ func (o *Rebuilder) wantAugment(ctx context.Context, treeID btrfsprim.ObjID, cho
 		}
 	}
 	if len(choicesWithDist) > 0 {
+		dlog.Infof(ctx, "augment(tree=%v): %v", treeID, maps.SortedKeys(choicesWithDist))
 		o.pendingAugments[treeID] = append(o.pendingAugments[treeID], choicesWithDist)
 	}
 }