diff --git a/pkg/snapshot/overlay.go b/pkg/snapshot/overlay.go index c4b61f80..ef997ea6 100644 --- a/pkg/snapshot/overlay.go +++ b/pkg/snapshot/overlay.go @@ -291,7 +291,14 @@ func (o *snapshotter) Stat(ctx context.Context, key string) (_ snapshots.Info, r } metrics.GRPCLatency.WithLabelValues("Stat").Observe(time.Since(start).Seconds()) }() + msStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("metastore.begin.start", trace.WithAttributes( + attribute.Bool("writable", false), + )) ctx, t, err := o.ms.TransactionContext(ctx, false) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.read.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return snapshots.Info{}, err } @@ -319,7 +326,14 @@ func (o *snapshotter) Update(ctx context.Context, info snapshots.Info, fieldpath metrics.GRPCLatency.WithLabelValues("Update").Observe(time.Since(start).Seconds()) }() + msStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("metastore.begin.start", trace.WithAttributes( + attribute.Bool("writable", true), + )) ctx, t, err := o.ms.TransactionContext(ctx, true) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.write.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return snapshots.Info{}, err } @@ -347,7 +361,14 @@ func (o *snapshotter) Usage(ctx context.Context, key string) (_ snapshots.Usage, metrics.GRPCLatency.WithLabelValues("Usage").Observe(time.Since(start).Seconds()) }() + msStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("metastore.begin.start", trace.WithAttributes( + attribute.Bool("writable", false), + )) ctx, t, err := o.ms.TransactionContext(ctx, false) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.read.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return snapshots.Usage{}, err } @@ -469,7 +490,22 @@ func (o *snapshotter) isPrepareRootfs(info snapshots.Info) bool { } func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, key string, parent string, opts ...snapshots.Opt) (_ []mount.Mount, retErr error) { + ctx, span := tracing.GetDefaultTracer().Start(ctx, "snapshotter.createMountPoint", trace.WithAttributes( + attribute.String("kind", kind.String()), + attribute.String("key", key), + attribute.String("parent", parent), + )) + defer span.End() + + msStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("metastore.begin.start", trace.WithAttributes( + attribute.Bool("writable", true), + )) ctx, t, err := o.ms.TransactionContext(ctx, true) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.done", trace.WithAttributes( + attribute.Bool("writable", true), + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return nil, err } @@ -483,10 +519,20 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, } }() + // Add detailed timing around pre-snapshot filesystem setup that happens before createSnapshot + fsPrepStart := time.Now() + + trace.SpanFromContext(ctx).AddEvent("before.createSnapshot", trace.WithAttributes( + attribute.String("kind", kind.String()), + attribute.String("parent", parent), + )) id, info, err := o.createSnapshot(ctx, kind, key, parent, opts) if err != nil { return nil, err } + trace.SpanFromContext(ctx).AddEvent("after.createSnapshot", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(fsPrepStart).Milliseconds())), + )) // Extract image reference for logging imageRef := "" if img, ok := info.Labels[label.CRIImageRef]; ok { @@ -496,6 +542,10 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, } log.G(ctx).Debugf("Creating snapshot %s for image: %s", id, imageRef) + trace.SpanFromContext(ctx).SetAttributes( + attribute.String("snapshot_id", id), + attribute.String("image_ref", imageRef), + ) hasOverlayBDBlob := false hasImageRef := false @@ -620,7 +670,17 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, stype := storageTypeNormal writeType := o.getWritableType(ctx, parentID, info) - // If Preparing for rootfs, find metadata from its parent (top layer), launch and mount backstore device. + // Post-commit actions decided during preparation when rootfs + var doPrepareWritableSpec bool + var updateSpecParentIsAccel bool + var updateSpecNeedRecord bool + var updateSpecRecordPath string + var needAttach bool + var attachObdID string + var attachFsType string + var attachMkfs bool + + // If Preparing for rootfs, find metadata from its parent (top layer), decide backstore actions. if o.isPrepareRootfs(info) { log.G(ctx).Infof("Preparing rootfs(%s). writeType: %s", s.ID, writeType) @@ -632,15 +692,15 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, } } + // Decide actions; defer heavy operations until after we commit the metastore tx + attachMkfs = parent == "" + if writeType != RoDir { if stype == storageTypeRemoteBlock || stype == storageTypeLocalBlock { // If the parent is a remote or local block, use local block for the writable child layer. log.G(ctx).Debugf("Using local block storage for writable snapshot %s (writeType: %s)", s.ID, writeType) stype = storageTypeLocalBlock - if err := o.constructOverlayBDSpec(ctx, key, true); err != nil { - log.G(ctx).Errorln(err.Error()) - return nil, err - } + doPrepareWritableSpec = true } else { // Fallback to normal overlayfs if the parent is not an overlaybd layer. stype = storageTypeNormal @@ -648,71 +708,35 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, } } - switch stype { - case storageTypeLocalBlock, storageTypeRemoteBlock: + if stype == storageTypeLocalBlock || stype == storageTypeRemoteBlock { if parent != "" { - parentIsAccelLayer := parentInfo.Labels[label.AccelerationLayer] == "yes" - needRecordTrace := info.Labels[label.RecordTrace] == "yes" - recordTracePath := info.Labels[label.RecordTracePath] + updateSpecParentIsAccel = parentInfo.Labels[label.AccelerationLayer] == "yes" + updateSpecNeedRecord = info.Labels[label.RecordTrace] == "yes" + updateSpecRecordPath = info.Labels[label.RecordTracePath] log.G(ctx).Infof("Prepare rootfs (sn: %s, parentIsAccelLayer: %t, needRecordTrace: %t, recordTracePath: %s)", - id, parentIsAccelLayer, needRecordTrace, recordTracePath) - - if parentIsAccelLayer { - log.G(ctx).Infof("get accel-layer in parent (id: %s)", id) - // If parent is already an acceleration layer, there is certainly no need to record trace. - // Just mark this layer to get accelerated (trace replay) - err = o.updateSpec(parentID, true, "") - if writeType != RoDir { - o.updateSpec(id, true, "") - } - } else if needRecordTrace && recordTracePath != "" { - err = o.updateSpec(parentID, false, recordTracePath) - if writeType != RoDir { - o.updateSpec(id, false, recordTracePath) - } - } else { - // For the compatibility of images which have no accel layer - err = o.updateSpec(parentID, false, "") - } - if err != nil { - return nil, errors.Wrapf(err, "updateSpec failed for snapshot %s", parentID) - } + id, updateSpecParentIsAccel, updateSpecNeedRecord, updateSpecRecordPath) } - var obdID string + // Decide attach parameters var obdInfo *snapshots.Info if writeType != RoDir { - obdID = id + attachObdID = id obdInfo = &info } else { - obdID = parentID + attachObdID = parentID obdInfo = &parentInfo } fsType, ok := obdInfo.Labels[label.OverlayBDBlobFsType] if !ok { if isTurboOCI, _, _ := o.checkTurboOCI(obdInfo.Labels); isTurboOCI { - _, fsType = o.turboOCIFsMeta(obdID) + _, fsType = o.turboOCIFsMeta(attachObdID) } else { log.G(ctx).Warnf("cannot get fs type from label, %v, using %s", obdInfo.Labels, fsType) fsType = o.defaultFsType } } - log.G(ctx).Debugf("attachAndMountBlockDevice (obdID: %s, writeType: %s, fsType %s, targetPath: %s)", - obdID, writeType, fsType, o.overlaybdTargetPath(obdID)) - if err = o.attachAndMountBlockDevice(ctx, obdID, writeType, fsType, parent == ""); err != nil { - log.G(ctx).Errorf("%v", err) - return nil, errors.Wrapf(err, "failed to attach and mount for snapshot %v", obdID) - } - - defer func() { - if retErr != nil && writeType == RwDir { // It's unnecessary to umount overlay block device if writeType == writeTypeRawDev - if rerr := mount.Unmount(o.overlaybdMountpoint(obdID), 0); rerr != nil { - log.G(ctx).WithError(rerr).Warnf("failed to umount writable block %s", o.overlaybdMountpoint(obdID)) - } - } - }() - default: - // do nothing + attachFsType = fsType + needAttach = true } } if _, writableBD := info.Labels[label.SupportReadWriteMode]; stype == storageTypeNormal && writableBD { @@ -726,6 +750,55 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, return nil, err } + // Perform heavy operations outside the metastore write transaction + if o.isPrepareRootfs(info) { + // If we decided to prepare writable overlaybd (runs overlaybd-create), do it now + if doPrepareWritableSpec { + if err := o.constructOverlayBDSpec(ctx, key, true); err != nil { + return nil, err + } + } + // Update spec flags if needed + if stype == storageTypeLocalBlock || stype == storageTypeRemoteBlock { + if parent != "" { + if updateSpecParentIsAccel { + if err := o.updateSpec(parentID, true, ""); err != nil { + return nil, errors.Wrapf(err, "updateSpec failed for snapshot %s", parentID) + } + if writeType != RoDir { + _ = o.updateSpec(id, true, "") + } + } else if updateSpecNeedRecord && updateSpecRecordPath != "" { + if err := o.updateSpec(parentID, false, updateSpecRecordPath); err != nil { + return nil, errors.Wrapf(err, "updateSpec failed for snapshot %s", parentID) + } + if writeType != RoDir { + _ = o.updateSpec(id, false, updateSpecRecordPath) + } + } else if parent != "" { + if err := o.updateSpec(parentID, false, ""); err != nil { + return nil, errors.Wrapf(err, "updateSpec failed for snapshot %s", parentID) + } + } + } + // Attach and mount device if needed + if needAttach { + log.G(ctx).Debugf("attachAndMountBlockDevice (obdID: %s, writeType: %s, fsType %s, targetPath: %s)", attachObdID, writeType, attachFsType, o.overlaybdTargetPath(attachObdID)) + if err = o.attachAndMountBlockDevice(ctx, attachObdID, writeType, attachFsType, attachMkfs); err != nil { + log.G(ctx).Errorf("%v", err) + return nil, errors.Wrapf(err, "failed to attach and mount for snapshot %v", attachObdID) + } + defer func() { + if retErr != nil && writeType == RwDir { + if rerr := mount.Unmount(o.overlaybdMountpoint(attachObdID), 0); rerr != nil { + log.G(ctx).WithError(rerr).Warnf("failed to umount writable block %s", o.overlaybdMountpoint(attachObdID)) + } + } + }() + } + } + } + var m []mount.Mount switch stype { case storageTypeNormal: @@ -762,6 +835,12 @@ func (o *snapshotter) createMountPoint(ctx context.Context, kind snapshots.Kind, // Prepare creates an active snapshot identified by key descending from the provided parent. func (o *snapshotter) Prepare(ctx context.Context, key, parent string, opts ...snapshots.Opt) (_ []mount.Mount, retErr error) { log.G(ctx).Infof("Prepare (key: %s, parent: %s)", key, parent) + ctx, span := tracing.GetDefaultTracer().Start(ctx, "snapshotter.Prepare", trace.WithAttributes( + attribute.String("key", key), + attribute.String("parent", parent), + attribute.Int("opts_count", len(opts)), + )) + defer span.End() // Extract labels from opts to see what's being passed to us. var allLabels map[string]string @@ -780,6 +859,7 @@ func (o *snapshotter) Prepare(ctx context.Context, key, parent string, opts ...s // Log what we received from containerd if len(allLabels) > 0 { log.G(ctx).Debugf("Prepare: Received %d labels from containerd", len(allLabels)) + span.SetAttributes(attribute.Int("labels_count", len(allLabels))) } else { log.G(ctx).Debugf("Prepare: No labels received from containerd (opts count: %d)", len(opts)) } @@ -834,7 +914,11 @@ func (o *snapshotter) Mounts(ctx context.Context, key string) (_ []mount.Mount, } metrics.GRPCLatency.WithLabelValues("Mounts").Observe(time.Since(start).Seconds()) }() + msStart := time.Now() ctx, t, err := o.ms.TransactionContext(ctx, false) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.read.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return nil, err } @@ -911,7 +995,11 @@ func (o *snapshotter) Commit(ctx context.Context, name, key string, opts ...snap metrics.GRPCLatency.WithLabelValues("Commit").Observe(time.Since(start).Seconds()) }() + msStart := time.Now() ctx, t, err := o.ms.TransactionContext(ctx, true) + trace.SpanFromContext(ctx).AddEvent("metastore.begin.write.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(msStart).Milliseconds())), + )) if err != nil { return err } @@ -1432,17 +1520,28 @@ func (o *snapshotter) createSnapshot(ctx context.Context, kind snapshots.Kind, k snapshotDir := filepath.Join(o.root, "snapshots") + prepStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("fs.prepareDirectory.start") td, err = o.prepareDirectory(ctx, snapshotDir, kind) if err != nil { return "", snapshots.Info{}, errors.Wrap(err, "failed to create prepare snapshot dir") } + trace.SpanFromContext(ctx).AddEvent("fs.prepareDirectory.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(prepStart).Milliseconds())), + )) + dbStart := time.Now() + trace.SpanFromContext(ctx).AddEvent("db.CreateSnapshot.start") s, err := storage.CreateSnapshot(ctx, kind, key, parent, opts...) if err != nil { return "", snapshots.Info{}, errors.Wrap(err, "failed to create snapshot") } + trace.SpanFromContext(ctx).AddEvent("db.CreateSnapshot.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(dbStart).Milliseconds())), + )) if len(s.ParentIDs) > 0 { + parentStart := time.Now() st, err := os.Stat(o.upperPath(s.ParentIDs[0])) if err != nil { return "", snapshots.Info{}, errors.Wrap(err, "failed to stat parent") @@ -1452,6 +1551,9 @@ func (o *snapshotter) createSnapshot(ctx context.Context, kind snapshots.Kind, k if err := os.Lchown(filepath.Join(td, "fs"), int(stat.Uid), int(stat.Gid)); err != nil { return "", snapshots.Info{}, errors.Wrap(err, "failed to chown") } + trace.SpanFromContext(ctx).AddEvent("fs.parent.stat_lchown.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(parentStart).Milliseconds())), + )) } // _, tmpinfo, _, err := storage.GetInfo(ctx, key) id, info, _, err := storage.GetInfo(ctx, key) @@ -1459,22 +1561,34 @@ func (o *snapshotter) createSnapshot(ctx context.Context, kind snapshots.Kind, k if diskQuotaSize := o.getDiskQuotaSize(&info); diskQuotaSize != "" { log.G(ctx).Infof("set usage quota %s for rootfs(sn: %s)", diskQuotaSize, s.ID) upperPath := filepath.Join(td, "fs") + quotaStart := time.Now() if err := o.setDiskQuota(ctx, upperPath, diskQuotaSize, diskquota.QuotaMinID); err != nil { return "", snapshots.Info{}, errors.Wrapf(err, "failed to set diskquota on upperpath, snapshot id: %s", s.ID) } + trace.SpanFromContext(ctx).AddEvent("diskquota.upper.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(quotaStart).Milliseconds())), + )) // if there's no parent, we just return a bind mount, so no need to set quota on workerpath if len(s.ParentIDs) > 0 { workpath := filepath.Join(td, "work") + quotaWorkStart := time.Now() if err := o.setDiskQuota(ctx, workpath, diskQuotaSize, diskquota.QuotaMinID); err != nil { return "", snapshots.Info{}, errors.Wrapf(err, "failed to set diskquota on workpath, snapshot id: %s", s.ID) } + trace.SpanFromContext(ctx).AddEvent("diskquota.work.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(quotaWorkStart).Milliseconds())), + )) } } } path = filepath.Join(snapshotDir, s.ID) + renStart := time.Now() if err = os.Rename(td, path); err != nil { return "", snapshots.Info{}, errors.Wrap(err, "failed to rename") } + trace.SpanFromContext(ctx).AddEvent("fs.rename.done", trace.WithAttributes( + attribute.Float64("duration_ms", float64(time.Since(renStart).Milliseconds())), + )) td = "" // id, info, _, err := storage.GetInfo(ctx, key) @@ -1502,6 +1616,10 @@ func (o *snapshotter) createSnapshot(ctx context.Context, kind snapshots.Kind, k } func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string, info snapshots.Info) (storageType, error) { + ctx, span := tracing.GetDefaultTracer().Start(ctx, "snapshotter.identifySnapshotStorageType", trace.WithAttributes( + attribute.String("snapshot_id", id), + )) + defer span.End() // Extract image reference for logging imageRef := "" if img, ok := info.Labels[label.CRIImageRef]; ok { @@ -1521,6 +1639,7 @@ func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string if hasBDBlobSize && hasBDBlobDigest { if hasRef || hasCriRef { + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "remote_block"))) return storageTypeRemoteBlock, nil } else { log.G(ctx).Warnf("Image %s (snapshot %s) has overlaybd blob metadata (blob-size=%t, blob-digest=%t) but missing critical image reference labels (target-ref=%t, cri-ref=%t).", @@ -1537,6 +1656,7 @@ func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string filePath := o.magicFilePath(id) st, err := o.identifyLocalStorageType(filePath) if err == nil { + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "local_by_magic"), attribute.Int("stype", int(st)))) return st, nil } log.G(ctx).Debugf("failed to identify by magic file %s, error %v, try to identify by sealed file/writable_data", filePath, err) @@ -1545,6 +1665,7 @@ func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string filePath = o.overlaybdSealedFilePath(id) st, err = o.identifyLocalStorageType(filePath) if err == nil { + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "local_by_sealed"), attribute.Int("stype", int(st)))) return st, nil } @@ -1559,6 +1680,7 @@ func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string filePath = o.overlaybdOCILayerPath(id) if _, err := os.Stat(filePath); err == nil { log.G(ctx).Infof("uncompressed layer found in sn: %s", id) + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "local_layer"))) return storageTypeLocalLayer, nil } if os.IsNotExist(err) { @@ -1567,13 +1689,16 @@ func (o *snapshotter) identifySnapshotStorageType(ctx context.Context, id string filePath = o.overlaybdConfPath(id) if _, err := os.Stat(filePath); err == nil { log.G(ctx).Debugf("%s/config.v1.json found, return storageTypeRemoteBlock", id) + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "remote_by_conf"))) return storageTypeRemoteBlock, nil } log.G(ctx).Debugf("Falling back to normal storage type for snapshot %s", id) + trace.SpanFromContext(ctx).AddEvent("identifyStorageType", trace.WithAttributes(attribute.String("identified", "normal_fallback"))) return storageTypeNormal, nil } log.G(ctx).Debugf("storageType(sn: %s): %d", id, st) + span.SetAttributes(attribute.Int("stype", int(st))) return st, err } diff --git a/pkg/snapshot/storage.go b/pkg/snapshot/storage.go index 4b56921c..87eb5436 100644 --- a/pkg/snapshot/storage.go +++ b/pkg/snapshot/storage.go @@ -37,6 +37,7 @@ import ( "go.opentelemetry.io/otel/propagation" "github.com/containerd/accelerated-container-image/pkg/label" + "github.com/containerd/accelerated-container-image/pkg/tracing" "github.com/containerd/accelerated-container-image/pkg/utils" "github.com/containerd/containerd/v2/core/images" "github.com/containerd/containerd/v2/core/mount" @@ -50,6 +51,8 @@ import ( specs "github.com/opencontainers/image-spec/specs-go/v1" "github.com/pkg/errors" "github.com/sirupsen/logrus" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "golang.org/x/sys/unix" ) @@ -256,10 +259,19 @@ func IsErofsFilesystem(path string) bool { // // TODO(fuweid): need to track the middle state if the process has been killed. func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string, writable string, fsType string, mkfs bool) (retErr error) { + ctx, span := tracing.GetDefaultTracer().Start(ctx, "snapshotter.attachAndMountBlockDevice", trace.WithAttributes( + attribute.String("snapshot_id", snID), + attribute.String("writable", writable), + attribute.String("fsType", fsType), + attribute.Bool("mkfs", mkfs), + )) + defer span.End() + log.G(ctx).Debugf("Starting block device attachment for snapshot %s (writable: %s, fsType: %s)", snID, writable, fsType) log.G(ctx).Debugf("lookup device mountpoint(%s) if exists before attach.", snID) mountPoint := o.overlaybdMountpoint(snID) + trace.SpanFromContext(ctx).AddEvent("lookup_mountpoint", trace.WithAttributes(attribute.String("mountpoint", mountPoint))) if err := lookup(mountPoint); err == nil { log.G(ctx).Debugf("device mountpoint(%s) already exists, skip attach.", mountPoint) return nil @@ -270,6 +282,7 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string } targetPath := o.overlaybdTargetPath(snID) + trace.SpanFromContext(ctx).AddEvent("configfs_target_begin", trace.WithAttributes(attribute.String("targetPath", targetPath))) err := os.MkdirAll(targetPath, 0700) if err != nil { return errors.Wrapf(err, "failed to create target dir for %s", targetPath) @@ -296,14 +309,27 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string targetPath, fmt.Sprintf("max_data_area_mb=%d", obdMaxDataAreaMB)) } - err = os.WriteFile(path.Join(targetPath, "enable"), ([]byte)("1"), 0666) - if err != nil { - // read the init-debug.log for readable - debugLogPath := o.overlaybdInitDebuglogPath(snID) - if data, derr := os.ReadFile(debugLogPath); derr == nil { - return errors.Errorf("failed to enable target for %s, %s", targetPath, data) + // Writing "1" to enable triggers synchronous TCMU/overlaybd device bring-up. + // The kernel sets up the target and completes a userspace handshake with + // tcmu-runner/overlaybd (reading config, opening files, allocating buffers). + // Under CPU/IO load this can block for a few hundred milliseconds before returning. + { + _, enableSpan := tracing.GetDefaultTracer().Start(ctx, "configfs.enable", trace.WithAttributes( + attribute.String("targetPath", targetPath), + )) + defer enableSpan.End() + + err = os.WriteFile(path.Join(targetPath, "enable"), ([]byte)("1"), 0666) + if err != nil { + enableSpan.RecordError(err) + enableSpan.SetAttributes(attribute.String("error", err.Error())) + // read the init-debug.log for readable + debugLogPath := o.overlaybdInitDebuglogPath(snID) + if data, derr := os.ReadFile(debugLogPath); derr == nil { + return errors.Errorf("failed to enable target for %s, %s", targetPath, data) + } + return errors.Wrapf(err, "failed to enable target for %s", targetPath) } - return errors.Wrapf(err, "failed to enable target for %s", targetPath) } // fixed by fuweid @@ -376,9 +402,12 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string } deviceNumber := strings.TrimSuffix(string(bytes), "\n") + //////////////////////////////////////// + // The device doesn't show up instantly. Need retry here. var lastErr error = nil for retry := 0; retry < maxAttachAttempts; retry++ { + trace.SpanFromContext(ctx).AddEvent("wait_block_device", trace.WithAttributes(attribute.Int("retry", retry))) devDirs, err := os.ReadDir(o.scsiBlockDevicePath(deviceNumber)) if err != nil { lastErr = err @@ -414,6 +443,7 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string } if mkfs { + trace.SpanFromContext(ctx).AddEvent("mkfs_begin", trace.WithAttributes(attribute.String("fstype", fstype))) args := []string{"-t", fstype} if len(options) > 2 { if options[2] != "" { @@ -463,6 +493,7 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string } log.G(ctx).Infof("fs type: %s, mount options: %s, rw: %s, mountpoint: %s", fstype, mountOpts, writable, mountPoint) + trace.SpanFromContext(ctx).AddEvent("mount_begin", trace.WithAttributes(attribute.String("fstype", fstype), attribute.String("mountOpts", mountOpts))) if err := unix.Mount(device, mountPoint, fstype, mountFlag, mountOpts); err != nil { lastErr = errors.Wrapf(err, "failed to mount %s to %s", device, mountPoint) time.Sleep(10 * time.Millisecond) @@ -478,6 +509,7 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string } args = append(args, device, mountPoint) log.G(ctx).Infof("fs type: %s, mount options: %v", fstype, args) + trace.SpanFromContext(ctx).AddEvent("mount_begin", trace.WithAttributes(attribute.String("fstype", fstype), attribute.StringSlice("args", args))) out, err := exec.CommandContext(ctx, "mount", args...).CombinedOutput() if err != nil { lastErr = errors.Wrapf(err, "failed to mount for dev %s: %s", device, out) @@ -495,15 +527,31 @@ func (o *snapshotter) attachAndMountBlockDevice(ctx context.Context, snID string // constructOverlayBDSpec generates the config spec for overlaybd target. func (o *snapshotter) constructOverlayBDSpec(ctx context.Context, key string, writable bool) error { - id, info, _, err := storage.GetInfo(ctx, key) + ctx, span := tracing.GetDefaultTracer().Start(ctx, "snapshotter.constructOverlayBDSpec", trace.WithAttributes( + attribute.String("key", key), + attribute.Bool("writable", writable), + )) + defer span.End() + + // Use a fresh read transaction for storage.GetInfo calls to avoid using a potentially + // closed tx from outer scopes. This is safe because we only read metadata here. + ctxTx, t, err := o.ms.TransactionContext(ctx, false) + if err != nil { + return err + } + defer t.Rollback() + + id, info, _, err := storage.GetInfo(ctxTx, key) if err != nil { return errors.Wrapf(err, "failed to get info for snapshot %s", key) } + span.SetAttributes(attribute.String("snapshot_id", id)) stype, err := o.identifySnapshotStorageType(ctx, id, info) if err != nil { return errors.Wrapf(err, "failed to identify storage of snapshot %s", key) } + span.SetAttributes(attribute.Int("storage_type", int(stype))) var carrier = propagation.MapCarrier{} otel.GetTextMapPropagator().Inject(ctx, carrier) @@ -515,7 +563,7 @@ func (o *snapshotter) constructOverlayBDSpec(ctx context.Context, key string, wr // load the parent's config and reuse the lowerdir if info.Parent != "" { - parentID, _, _, err := storage.GetInfo(ctx, info.Parent) + parentID, _, _, err := storage.GetInfo(ctxTx, info.Parent) if err != nil { return errors.Wrapf(err, "failed to get info for parent snapshot %s", info.Parent) } @@ -689,6 +737,7 @@ func (o *snapshotter) constructOverlayBDSpec(ctx context.Context, key string, wr configJSON.Lowers = newLowers } } + span.SetAttributes(attribute.Int("lowers_count", len(configJSON.Lowers))) configBuffer, _ := json.MarshalIndent(configJSON, "", " ") log.G(ctx).Infoln(string(configBuffer)) return o.atomicWriteOverlaybdTargetConfig(id, &configJSON)