Add more detailed timing statistics:

* Calculate average latency for FUSE operations.

* Add generic latency stats collection for PathFilesystems.

example/Makefile

 # Use "gomake install" to build and install this package.
 include $(GOROOT)/src/Make.inc
 
-all: loopback multizip
-
-# Start c&p make.cmd
-%: %._.$O
-	$(LD) -o $@ $<
-
-%._.$O: %.go $(PREREQ)
-	$(GC) -o $@ $<
-# end c&p
-
+TARG=loopback
+GOFILES=loopback.go
 DEPS=../examplelib ../fuse
 
 include $(GOROOT)/src/Make.cmd

example/loopback.go

@@ -7,9 +7,7 @@ import (
 	"github.com/hanwen/go-fuse/fuse"
 	"fmt"
 	"os"
-	"expvar"
 	"flag"
-	"strings"
 	"runtime"
 )
 
@@ -26,6 +24,7 @@ func main() {
 
 	orig := flag.Arg(0)
 	fs := fuse.NewLoopbackFileSystem(orig)
+	timing := fuse.NewTimingPathFilesystem(fs)
 
 	var opts fuse.PathFileSystemConnectorOptions
 
@@ -35,7 +34,7 @@ func main() {
 
 	fs.SetOptions(&opts)
 
-	conn := fuse.NewPathFileSystemConnector(fs)
+	conn := fuse.NewPathFileSystemConnector(timing)
 	state := fuse.NewMountState(conn)
 	state.Debug = *debug
 
@@ -56,9 +55,13 @@ func main() {
 	state.Loop(*threaded)
 	fmt.Println("Finished", state.Stats())
 
-	for v := range expvar.Iter() {
-		if strings.HasPrefix(v.Key, "fuse_") {
-			fmt.Printf("%v: %v\n", v.Key, v.Value)
-		}
-	}
+	counts := state.OperationCounts()
+
+	fmt.Println("Counts: ", counts)
+
+	latency := state.Latencies()
+	fmt.Println("Latency (ms):", latency)
+
+	latency = timing.Latencies()
+	fmt.Println("Path ops (ms):", latency)
 }

fuse/Makefile

@@ -14,7 +14,8 @@ GOFILES=misc.go\
 	default.go \
 	datafile.go \
 	loopback.go \
-	wrappedfs.go
+	wrappedfs.go \
+	timingfs.go
 
 include $(GOROOT)/src/Make.pkg
 

fuse/fuse.go

@@ -77,8 +77,9 @@ type MountState struct {
 	// For efficient reads.
 	buffers *BufferPool
 
-	operationCounts *expvar.Map
-	operationLatencies *expvar.Map
+	statisticsMutex    sync.Mutex
+	operationCounts    map[string]int64
+	operationLatencies map[string]int64
 }
 
 func (me *MountState) RegisterFile(file RawFuseFile) uint64 {
@@ -139,8 +140,8 @@ func (me *MountState) Mount(mountPoint string) os.Error {
 	me.mountPoint = mp
 	me.mountFile = file
 
-	me.operationCounts = expvar.NewMap(fmt.Sprintf("fuse_op_count(%v)", mountPoint))
-	me.operationLatencies = expvar.NewMap(fmt.Sprintf("fuse_op_latency_ms(%v)", mountPoint))
+	me.operationCounts = make(map[string]int64)
+	me.operationLatencies = make(map[string]int64)
 	return nil
 }
 
@@ -214,6 +215,29 @@ func NewMountState(fs RawFileSystem) *MountState {
 }
 
 // TODO - have more statistics.
+func (me *MountState) Latencies() map[string]float64 {
+	me.statisticsMutex.Lock()
+	defer me.statisticsMutex.Unlock()
+
+	r := make(map[string]float64)
+	for k, v := range me.operationCounts {
+		r[k] = float64(me.operationLatencies[k]) / float64(v)
+	}
+
+	return r
+}
+
+func (me *MountState) OperationCounts() map[string]int64 {
+	me.statisticsMutex.Lock()
+	defer me.statisticsMutex.Unlock()
+
+	r := make(map[string]int64)
+	for k, v := range me.operationCounts {
+		r[k] = v
+	}
+	return r
+}
+
 func (me *MountState) Stats() string {
 	var lines []string
 
@@ -263,8 +287,13 @@ func (me *MountState) newFuseRequest() (*fuseRequest, os.Error) {
 
 func (me *MountState) discardFuseRequest(req *fuseRequest) {
 	dt := time.Nanoseconds() - req.startNs
-	me.operationLatencies.Add(operationName(req.inHeader.Opcode),
-		dt / 1e6)
+
+	me.statisticsMutex.Lock()
+	defer me.statisticsMutex.Unlock()
+
+	key := operationName(req.inHeader.Opcode)
+	me.operationCounts[key] += 1
+	me.operationLatencies[key] += dt / 1e6
 
 	me.buffers.FreeBuffer(req.inputBuf)
 	me.buffers.FreeBuffer(req.flatData)
@@ -325,7 +354,6 @@ func (me *MountState) handle(req *fuseRequest) {
 func (me *MountState) dispatch(req *fuseRequest) {
 	// TODO - would be nice to remove this logging from the critical path.
 	h := &req.inHeader
-	me.operationCounts.Add(operationName(h.Opcode), 1)
 
 	input := newInput(h.Opcode)
 	if input != nil && !parseLittleEndian(req.arg, input) {

fuse/timingfs.go

+package fuse
+
+import (
+	"sync"
+	"time"
+)
+
+
+type TimingPathFilesystem struct {
+	original PathFilesystem
+
+	statisticsLock sync.Mutex
+	latencies      map[string]int64
+	counts         map[string]int64
+}
+
+func NewTimingPathFilesystem(fs PathFilesystem) *TimingPathFilesystem {
+	t := new(TimingPathFilesystem)
+	t.original = fs
+	t.latencies = make(map[string]int64)
+	t.counts = make(map[string]int64)
+	return t
+}
+
+func (me *TimingPathFilesystem) startTimer(name string) (closure func()) {
+	start := time.Nanoseconds()
+
+	return func() {
+		dt := (time.Nanoseconds() - start) / 1e6
+		me.statisticsLock.Lock()
+		defer me.statisticsLock.Unlock()
+
+		me.counts[name] += 1
+		me.latencies[name] += dt
+	}
+}
+
+func (me *TimingPathFilesystem) Latencies() map[string]float64 {
+	me.statisticsLock.Lock()
+	defer me.statisticsLock.Unlock()
+
+	r := make(map[string]float64)
+	for k, v := range me.counts {
+		r[k] = float64(me.latencies[k]) / float64(v)
+	}
+	return r
+}
+
+func (me *TimingPathFilesystem) GetAttr(name string) (*Attr, Status) {
+	defer me.startTimer("GetAttr")()
+	return me.original.GetAttr(name)
+}
+
+func (me *TimingPathFilesystem) Readlink(name string) (string, Status) {
+	defer me.startTimer("Readlink")()
+	return me.original.Readlink(name)
+}
+
+func (me *TimingPathFilesystem) Mknod(name string, mode uint32, dev uint32) Status {
+	defer me.startTimer("Mknod")()
+	return me.original.Mknod(name, mode, dev)
+}
+
+func (me *TimingPathFilesystem) Mkdir(name string, mode uint32) Status {
+	defer me.startTimer("Mkdir")()
+	return me.original.Mkdir(name, mode)
+}
+
+func (me *TimingPathFilesystem) Unlink(name string) (code Status) {
+	defer me.startTimer("Unlink")()
+	return me.original.Unlink(name)
+}
+
+func (me *TimingPathFilesystem) Rmdir(name string) (code Status) {
+	defer me.startTimer("Rmdir")()
+	return me.original.Rmdir(name)
+}
+
+func (me *TimingPathFilesystem) Symlink(value string, linkName string) (code Status) {
+	defer me.startTimer("Symlink")()
+	return me.original.Symlink(value, linkName)
+}
+
+func (me *TimingPathFilesystem) Rename(oldName string, newName string) (code Status) {
+	defer me.startTimer("Rename")()
+	return me.original.Rename(oldName, newName)
+}
+
+func (me *TimingPathFilesystem) Link(oldName string, newName string) (code Status) {
+	defer me.startTimer("Link")()
+	return me.original.Link(oldName, newName)
+}
+
+func (me *TimingPathFilesystem) Chmod(name string, mode uint32) (code Status) {
+	defer me.startTimer("Chmod")()
+	return me.original.Chmod(name, mode)
+}
+
+func (me *TimingPathFilesystem) Chown(name string, uid uint32, gid uint32) (code Status) {
+	defer me.startTimer("Chown")()
+	return me.original.Chown(name, uid, gid)
+}
+
+func (me *TimingPathFilesystem) Truncate(name string, offset uint64) (code Status) {
+	defer me.startTimer("Truncate")()
+	return me.original.Truncate(name, offset)
+}
+
+func (me *TimingPathFilesystem) Open(name string, flags uint32) (file RawFuseFile, code Status) {
+	defer me.startTimer("Open")()
+	return me.original.Open(name, flags)
+}
+
+func (me *TimingPathFilesystem) OpenDir(name string) (stream chan DirEntry, status Status) {
+	defer me.startTimer("OpenDir")()
+	return me.original.OpenDir(name)
+}
+
+func (me *TimingPathFilesystem) Mount(conn *PathFileSystemConnector) Status {
+	defer me.startTimer("Mount")()
+	return me.original.Mount(conn)
+}
+
+func (me *TimingPathFilesystem) Unmount() {
+	defer me.startTimer("Unmount")()
+	me.original.Unmount()
+}
+
+func (me *TimingPathFilesystem) Access(name string, mode uint32) (code Status) {
+	defer me.startTimer("Access")()
+	return me.original.Access(name, mode)
+}
+
+func (me *TimingPathFilesystem) Create(name string, flags uint32, mode uint32) (file RawFuseFile, code Status) {
+	defer me.startTimer("Create")()
+	return me.original.Create(name, flags, mode)
+}
+
+func (me *TimingPathFilesystem) Utimens(name string, AtimeNs uint64, CtimeNs uint64) (code Status) {
+	defer me.startTimer("Utimens")()
+	return me.original.Utimens(name, AtimeNs, CtimeNs)
+}