Add more timing hooks to TimingPathFilesystem.

example/loopback.go

@@ -10,8 +10,12 @@ import (
 	"flag"
 	"runtime"
 	"sort"
+	"log"
 )
 
+var _ = runtime.GOMAXPROCS
+var _ = log.Print
+
 func PrintMap(m map[string]float64)  {
 	keys := make([]string, len(m))
 	for k, _ := range m {
@@ -43,15 +47,16 @@ func main() {
 
 	var opts fuse.PathFileSystemConnectorOptions
 
-	opts.AttrTimeout = 1.0
-	opts.EntryTimeout = 1.0
-	opts.NegativeTimeout = 1.0
+	opts.AttrTimeout = 0.0
+	opts.EntryTimeout = 0.0
+	opts.NegativeTimeout = 0.0
 
-	fs.SetOptions(&opts)
+	fs.FillOptions(&opts)
 
 	conn := fuse.NewPathFileSystemConnector(timing)
 	rawTiming := fuse.NewTimingRawFilesystem(conn)
-	
+	conn.SetOptions(opts)
+
 	state := fuse.NewMountState(rawTiming)
 	state.Debug = *debug
 
@@ -61,27 +66,34 @@ func main() {
 		fmt.Printf("MountFuse fail: %v\n", err)
 		os.Exit(1)
 	}
-	// TODO - figure out what a good value is.
-	cpus := 1
-	// 	cpus := fuse.CountCpus()
-	if cpus > 1 {
-		runtime.GOMAXPROCS(cpus)
-	}
 
-	fmt.Printf("Mounted %s on %s (threaded=%v, debug=%v, cpus=%v)\n", orig, mountPoint, *threaded, *debug, cpus)
+	fmt.Printf("Mounted %s on %s (threaded=%v, debug=%v)\n", orig, mountPoint, *threaded, *debug)
 	state.Loop(*threaded)
 	fmt.Println("Finished", state.Stats())
 
+	fmt.Println("\n\nMountState statistics\n")
 	counts := state.OperationCounts()
 	fmt.Println("Counts: ", counts)
 
 	latency := state.Latencies()
-	fmt.Println("MountState latency (ms):")
+	fmt.Println("Operation latency (ms):")
 	PrintMap(latency)
 
+	latency = rawTiming.Latencies()
+	fmt.Println("\n\nRaw FS (ms):", latency)
+
+	fmt.Println("\n\nLoopback FS statistics\n")
 	latency = timing.Latencies()
-	fmt.Println("Path ops (ms):", latency)
+	fmt.Println("Latency (ms):", latency)
 
-	latency = rawTiming.Latencies()
-	fmt.Println("Raw FS (ms):", latency)
+	fmt.Println("Operation counts:", timing.OperationCounts())
+
+	hot, unique := timing.HotPaths("GetAttr")
+	top := 200
+	start := len(hot)-top
+	if start < 0 {
+		start = 0
+	}
+	fmt.Printf("Unique GetAttr paths: %d\n", unique)
+	fmt.Printf("Top %d GetAttr paths: %v", top, hot[start:])
 }

fuse/timingfs.go

@@ -4,9 +4,12 @@ import (
 	"sync"
 	"time"
 	"log"
+	"fmt"
+	"sort"
 )
 
 var _ = log.Print
+var _ = fmt.Print
 
 // TimingPathFilesystem is a wrapper to collect timings for a PathFilesystem
 type TimingPathFilesystem struct {
@@ -15,6 +18,7 @@ type TimingPathFilesystem struct {
 	statisticsLock sync.Mutex
 	latencies      map[string]int64
 	counts         map[string]int64
+	pathCounts     map[string]map[string]int64
 }
 
 func NewTimingPathFilesystem(fs PathFilesystem) *TimingPathFilesystem {
@@ -22,10 +26,11 @@ func NewTimingPathFilesystem(fs PathFilesystem) *TimingPathFilesystem {
 	t.original = fs
 	t.latencies = make(map[string]int64)
 	t.counts = make(map[string]int64)
+	t.pathCounts = make(map[string]map[string]int64)
 	return t
 }
 
-func (me *TimingPathFilesystem) startTimer(name string) (closure func()) {
+func (me *TimingPathFilesystem) startTimer(name string, arg string) (closure func()) {
 	start := time.Nanoseconds()
 
 	return func() {
@@ -35,9 +40,27 @@ func (me *TimingPathFilesystem) startTimer(name string) (closure func()) {
 
 		me.counts[name] += 1
 		me.latencies[name] += dt
+
+		m, ok := me.pathCounts[name]
+		if !ok {
+			m = make(map[string]int64)
+			me.pathCounts[name] = m
+		}
+		m[arg] += 1
 	}
 }
 
+func (me *TimingPathFilesystem) OperationCounts() map[string]int64 {
+	me.statisticsLock.Lock()
+	defer me.statisticsLock.Unlock()
+
+	r := make(map[string]int64)
+	for k, v := range me.counts {
+		r[k] = v
+	}
+	return r
+}
+
 func (me *TimingPathFilesystem) Latencies() map[string]float64 {
 	me.statisticsLock.Lock()
 	defer me.statisticsLock.Unlock()
@@ -49,103 +72,116 @@ func (me *TimingPathFilesystem) Latencies() map[string]float64 {
 	return r
 }
 
+func (me *TimingPathFilesystem) HotPaths(operation string) (paths []string, uniquePaths int) {
+	me.statisticsLock.Lock()
+	defer me.statisticsLock.Unlock()
+
+	counts := me.pathCounts[operation]
+	results := make([]string, 0, len(counts))
+	for k, v := range counts {
+		results = append(results, fmt.Sprintf("% 9d %s", v, k))
+
+	}
+	sort.SortStrings(results)
+	return results, len(counts)
+}
+
 func (me *TimingPathFilesystem) GetAttr(name string) (*Attr, Status) {
-	defer me.startTimer("GetAttr")()
+	defer me.startTimer("GetAttr", name)()
 	return me.original.GetAttr(name)
 }
 
-
 func (me *TimingPathFilesystem) GetXAttr(name string, attr string) ([]byte, Status) {
-	defer me.startTimer("GetXAttr")()
+	defer me.startTimer("GetXAttr", name)()
 	return me.original.GetXAttr(name, attr)
 }
 
 func (me *TimingPathFilesystem) Readlink(name string) (string, Status) {
-	defer me.startTimer("Readlink")()
+	defer me.startTimer("Readlink", name)()
 	return me.original.Readlink(name)
 }
 
 func (me *TimingPathFilesystem) Mknod(name string, mode uint32, dev uint32) Status {
-	defer me.startTimer("Mknod")()
+	defer me.startTimer("Mknod", name)()
 	return me.original.Mknod(name, mode, dev)
 }
 
 func (me *TimingPathFilesystem) Mkdir(name string, mode uint32) Status {
-	defer me.startTimer("Mkdir")()
+	defer me.startTimer("Mkdir", name)()
 	return me.original.Mkdir(name, mode)
 }
 
 func (me *TimingPathFilesystem) Unlink(name string) (code Status) {
-	defer me.startTimer("Unlink")()
+	defer me.startTimer("Unlink", name)()
 	return me.original.Unlink(name)
 }
 
 func (me *TimingPathFilesystem) Rmdir(name string) (code Status) {
-	defer me.startTimer("Rmdir")()
+	defer me.startTimer("Rmdir", name)()
 	return me.original.Rmdir(name)
 }
 
 func (me *TimingPathFilesystem) Symlink(value string, linkName string) (code Status) {
-	defer me.startTimer("Symlink")()
+	defer me.startTimer("Symlink", linkName)()
 	return me.original.Symlink(value, linkName)
 }
 
 func (me *TimingPathFilesystem) Rename(oldName string, newName string) (code Status) {
-	defer me.startTimer("Rename")()
+	defer me.startTimer("Rename", oldName)()
 	return me.original.Rename(oldName, newName)
 }
 
 func (me *TimingPathFilesystem) Link(oldName string, newName string) (code Status) {
-	defer me.startTimer("Link")()
+	defer me.startTimer("Link", newName)()
 	return me.original.Link(oldName, newName)
 }
 
 func (me *TimingPathFilesystem) Chmod(name string, mode uint32) (code Status) {
-	defer me.startTimer("Chmod")()
+	defer me.startTimer("Chmod", name)()
 	return me.original.Chmod(name, mode)
 }
 
 func (me *TimingPathFilesystem) Chown(name string, uid uint32, gid uint32) (code Status) {
-	defer me.startTimer("Chown")()
+	defer me.startTimer("Chown", name)()
 	return me.original.Chown(name, uid, gid)
 }
 
 func (me *TimingPathFilesystem) Truncate(name string, offset uint64) (code Status) {
-	defer me.startTimer("Truncate")()
+	defer me.startTimer("Truncate", name)()
 	return me.original.Truncate(name, offset)
 }
 
 func (me *TimingPathFilesystem) Open(name string, flags uint32) (file RawFuseFile, code Status) {
-	defer me.startTimer("Open")()
+	defer me.startTimer("Open", name)()
 	return me.original.Open(name, flags)
 }
 
 func (me *TimingPathFilesystem) OpenDir(name string) (stream chan DirEntry, status Status) {
-	defer me.startTimer("OpenDir")()
+	defer me.startTimer("OpenDir", name)()
 	return me.original.OpenDir(name)
 }
 
 func (me *TimingPathFilesystem) Mount(conn *PathFileSystemConnector) Status {
-	defer me.startTimer("Mount")()
+	defer me.startTimer("Mount", "")()
 	return me.original.Mount(conn)
 }
 
 func (me *TimingPathFilesystem) Unmount() {
-	defer me.startTimer("Unmount")()
+	defer me.startTimer("Unmount", "")()
 	me.original.Unmount()
 }
 
 func (me *TimingPathFilesystem) Access(name string, mode uint32) (code Status) {
-	defer me.startTimer("Access")()
+	defer me.startTimer("Access", name)()
 	return me.original.Access(name, mode)
 }
 
 func (me *TimingPathFilesystem) Create(name string, flags uint32, mode uint32) (file RawFuseFile, code Status) {
-	defer me.startTimer("Create")()
+	defer me.startTimer("Create", name)()
 	return me.original.Create(name, flags, mode)
 }
 
 func (me *TimingPathFilesystem) Utimens(name string, AtimeNs uint64, CtimeNs uint64) (code Status) {
-	defer me.startTimer("Utimens")()
+	defer me.startTimer("Utimens", name)()
 	return me.original.Utimens(name, AtimeNs, CtimeNs)
 }