Improved per-PID trace output.

fuseops/common_op.go

@@ -38,32 +38,21 @@ var fTraceByPID = flag.Bool(
 
 // A helper for embedding common behavior.
 type commonOp struct {
-	opType      string
-	r           bazilfuse.Request
+	// The op in which this struct is embedded, and a short description of it.
+	op Op
+
+	// The underlying bazilfuse request for this op.
+	bazilReq bazilfuse.Request
+
+	// Dependencies.
 	log         func(int, string, ...interface{})
 	opsInFlight *sync.WaitGroup
 
+	// Context and tracing information.
 	ctx    context.Context
 	report reqtrace.ReportFunc
 }
 
-func describeOpType(t reflect.Type) (desc string) {
-	name := t.String()
-
-	// The usual case: a string that looks like "*fuseops.GetInodeAttributesOp".
-	const prefix = "*fuseops."
-	const suffix = "Op"
-	if strings.HasPrefix(name, prefix) && strings.HasSuffix(name, suffix) {
-		desc = name[len(prefix) : len(name)-len(suffix)]
-		return
-	}
-
-	// Otherwise, it's not clear what to do.
-	desc = t.String()
-
-	return
-}
-
 var gPIDMapMu sync.Mutex
 
 // A map from PID to a traced context for that PID.
@@ -133,7 +122,7 @@ func (o *commonOp) maybeTraceByPID(
 
 	// Set up a new one and stick it in the map.
 	var report reqtrace.ReportFunc
-	out, report = reqtrace.Trace(in, fmt.Sprintf("PID %v", pid))
+	out, report = reqtrace.Trace(in, fmt.Sprintf("Requests from PID %v", pid))
 	gPIDMap[pid] = out
 
 	// Ensure we close the trace and remove it from the map eventually.
@@ -142,27 +131,44 @@ func (o *commonOp) maybeTraceByPID(
 	return
 }
 
+func (o *commonOp) ShortDesc() (desc string) {
+	opName := reflect.TypeOf(o.op).String()
+
+	// Attempt to better handle the usual case: a string that looks like
+	// "*fuseops.GetInodeAttributesOp".
+	const prefix = "*fuseops."
+	const suffix = "Op"
+	if strings.HasPrefix(opName, prefix) && strings.HasSuffix(opName, suffix) {
+		opName = opName[len(prefix) : len(opName)-len(suffix)]
+	}
+
+	// Include the inode number to which the op applies.
+	desc = fmt.Sprintf("%s(inode=%v)", opName, o.bazilReq.Hdr().Node)
+
+	return
+}
+
 func (o *commonOp) init(
 	ctx context.Context,
-	opType reflect.Type,
-	r bazilfuse.Request,
+	op Op,
+	bazilReq bazilfuse.Request,
 	log func(int, string, ...interface{}),
 	opsInFlight *sync.WaitGroup) {
 	// Set up a context that reflects per-PID tracing if appropriate.
-	ctx = o.maybeTraceByPID(ctx, int(r.Hdr().Pid))
+	ctx = o.maybeTraceByPID(ctx, int(bazilReq.Hdr().Pid))
 
 	// Initialize basic fields.
-	o.opType = describeOpType(opType)
-	o.r = r
+	o.op = op
+	o.bazilReq = bazilReq
 	o.log = log
 	o.opsInFlight = opsInFlight
 
 	// Set up a trace span for this op.
-	o.ctx, o.report = reqtrace.StartSpan(ctx, o.opType)
+	o.ctx, o.report = reqtrace.StartSpan(ctx, o.op.ShortDesc())
 }
 
 func (o *commonOp) Header() OpHeader {
-	bh := o.r.Hdr()
+	bh := o.bazilReq.Hdr()
 	return OpHeader{
 		Uid: bh.Uid,
 		Gid: bh.Gid,
@@ -187,27 +193,27 @@ func (o *commonOp) respondErr(err error) {
 
 	o.Logf(
 		"-> (%s) error: %v",
-		o.opType,
+		o.op.ShortDesc(),
 		err)
 
-	o.r.RespondError(err)
+	o.bazilReq.RespondError(err)
 }
 
 // Respond with the supplied response struct, which must be accepted by a
-// method called Respond on o.r.
+// method called Respond on o.bazilReq.
 //
-// Special case: nil means o.r.Respond accepts no parameters.
+// Special case: nil means o.bazilReq.Respond accepts no parameters.
 func (o *commonOp) respond(resp interface{}) {
 	// We were successful.
 	o.report(nil)
 
 	// Find the Respond method.
-	v := reflect.ValueOf(o.r)
+	v := reflect.ValueOf(o.bazilReq)
 	respond := v.MethodByName("Respond")
 
 	// Special case: handle successful ops with no response struct.
 	if resp == nil {
-		o.Logf("-> (%s) OK", o.opType)
+		o.Logf("-> (%s) OK", o.op.ShortDesc())
 		respond.Call([]reflect.Value{})
 		return
 	}

fuseops/convert.go

@@ -15,7 +15,6 @@
 package fuseops
 
 import (
-	"reflect"
 	"sync"
 	"time"
 
@@ -216,7 +215,7 @@ func Convert(
 		return
 	}
 
-	co.init(parentCtx, reflect.TypeOf(o), r, logForOp, opsInFlight)
+	co.init(parentCtx, o, r, logForOp, opsInFlight)
 	return
 }
 

fuseops/ops.go

@@ -18,6 +18,7 @@
 package fuseops
 
 import (
+	"fmt"
 	"os"
 	"time"
 
@@ -29,6 +30,9 @@ import (
 // to find particular concrete types, responding with fuse.ENOSYS if a type is
 // not supported.
 type Op interface {
+	// A short description of the op, to be used in logging.
+	ShortDesc() string
+
 	// Return the fields common to all operations.
 	Header() OpHeader
 
@@ -140,6 +144,11 @@ type LookUpInodeOp struct {
 	Entry ChildInodeEntry
 }
 
+func (o *LookUpInodeOp) ShortDesc() (desc string) {
+	desc = fmt.Sprintf("LookUpInode(parent=%v, name=%q)", o.Parent, o.Name)
+	return
+}
+
 func (o *LookUpInodeOp) Respond(err error) {
 	defer o.commonOp.opsInFlight.Done()
 
@@ -314,6 +323,11 @@ type MkDirOp struct {
 	Entry ChildInodeEntry
 }
 
+func (o *MkDirOp) ShortDesc() (desc string) {
+	desc = fmt.Sprintf("MkDir(parent=%v, name=%q)", o.Parent, o.Name)
+	return
+}
+
 func (o *MkDirOp) Respond(err error) {
 	defer o.commonOp.opsInFlight.Done()
 
@@ -371,6 +385,11 @@ type CreateFileOp struct {
 	Handle HandleID
 }
 
+func (o *CreateFileOp) ShortDesc() (desc string) {
+	desc = fmt.Sprintf("CreateFile(parent=%v, name=%q)", o.Parent, o.Name)
+	return
+}
+
 func (o *CreateFileOp) Respond(err error) {
 	defer o.commonOp.opsInFlight.Done()