Measure server side latencies too; simplify latencymap.

On T60, for each file we have
- Client side latency is 360us
- 106us of this is server side latency (4.5x lookup 23us, 1x getattr 4us) 
- 16.5us is due to latency measurement (time.Now() calls)
- 3us is due to garbage collection.

README

@@ -79,10 +79,17 @@ interface, all kernel caching turned off, median stat time:
 
 platform                    libfuse     Go-FUSE      difference (%)
 
-Lenovo T60/Fedora17 (1cpu)  349us       355us        2% slower
+Lenovo T60/Fedora16 (1cpu)  349us       355us        2% slower
 Lenovo T400/Lucid   (1cpu)  138us       140us        5% slower
 Dell T3500/Lucid    (1cpu)   72us        76us        5% slower
 
+On T60, for each file we have
+- Client side latency is 360us
+- 106us of this is server side latency (4.5x lookup 23us, 1x getattr 4us) 
+- 16.5us is due to latency measurements.
+- 3us is due to garbage collection.
+
+
 
 CREDITS
 

benchmark/stat_test.go

@@ -28,10 +28,17 @@ func setupFs(fs fuse.FileSystem) (string, func()) {
 	if err != nil {
 		panic(fmt.Sprintf("cannot mount %v", err)) // ugh - benchmark has no error methods.
 	}
+	state.SetRecordStatistics(true)
 	// state.Debug = true
 	go state.Loop()
 
 	return mountPoint, func() {
+		lc, lns := state.Latencies().Get("LOOKUP")
+		gc, gns := state.Latencies().Get("GETATTR")
+		fmt.Printf("GETATTR %dus/call n=%d, LOOKUP %dus/call n=%d\n",
+			gns / int64(1000 * lc), gc,
+			lns / int64(1000 * lc), lc)
+		
 		err := state.Unmount()
 		if err != nil {
 			log.Println("error during unmount", err)
@@ -110,7 +117,6 @@ func TestingBOnePass(b *testing.B, threads int, files []string) (results []float
 	runtime.ReadMemStats(&before)
 	
 	todo := b.N
-
 	for todo > 0 {
 		if len(files) > todo {
 			files = files[:todo]
@@ -128,6 +134,13 @@ func TestingBOnePass(b *testing.B, threads int, files []string) (results []float
 	return results
 }
 
+// Add this so we can estimate impact on latency numbers. 
+func BenchmarkTimeNow(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		time.Now()
+	}
+}
+
 func BenchmarkCFuseThreadedStat(b *testing.B) {
 	b.StopTimer()
 

fuse/latencymap.go

 package fuse
 
 import (
-	"fmt"
-	"sort"
 	"sync"
 )
 
@@ -11,40 +9,31 @@ type latencyMapEntry struct {
 	ns    int64
 }
 
-type LatencyArg struct {
-	Name string
-	Arg  string
-	DtNs int64
-}
-
 type LatencyMap struct {
 	sync.Mutex
 	stats          map[string]*latencyMapEntry
-	secondaryStats map[string]map[string]int64
 }
 
 func NewLatencyMap() *LatencyMap {
 	m := &LatencyMap{}
 	m.stats = make(map[string]*latencyMapEntry)
-	m.secondaryStats = make(map[string]map[string]int64)
 	return m
 }
 
-func (m *LatencyMap) AddMany(args []LatencyArg) {
+func (m *LatencyMap) Get(name string) (count int, dtNs int64) {
 	m.Mutex.Lock()
-	for _, v := range args {
-		m.add(v.Name, v.Arg, v.DtNs)
-	}
+	l := m.stats[name]
 	m.Mutex.Unlock()
+	return l.count, l.ns
 }
 
-func (m *LatencyMap) Add(name string, arg string, dtNs int64) {
+func (m *LatencyMap) Add(name string, dtNs int64) {
 	m.Mutex.Lock()
-	m.add(name, arg, dtNs)
+	m.add(name, dtNs)
 	m.Mutex.Unlock()
 }
 
-func (m *LatencyMap) add(name string, arg string, dtNs int64) {
+func (m *LatencyMap) add(name string, dtNs int64) {
 	e := m.stats[name]
 	if e == nil {
 		e = new(latencyMapEntry)
@@ -53,13 +42,6 @@ func (m *LatencyMap) add(name string, arg string, dtNs int64) {
 
 	e.count++
 	e.ns += dtNs
-	if arg != "" {
-		_, ok := m.secondaryStats[name]
-		if !ok {
-			m.secondaryStats[name] = make(map[string]int64)
-		}
-		// TODO - do something with secondaryStats[name]
-	}
 }
 
 func (m *LatencyMap) Counts() map[string]int {
@@ -87,15 +69,3 @@ func (m *LatencyMap) Latencies(unit float64) map[string]float64 {
 
 	return r
 }
-
-func (m *LatencyMap) TopArgs(name string) []string {
-	m.Mutex.Lock()
-	counts := m.secondaryStats[name]
-	results := make([]string, 0, len(counts))
-	for k, v := range counts {
-		results = append(results, fmt.Sprintf("% 9d %s", v, k))
-	}
-	m.Mutex.Unlock()
-	sort.Strings(results)
-	return results
-}

fuse/latencymap_test.go

@@ -9,8 +9,8 @@ var _ = fmt.Println
 
 func TestLatencyMap(t *testing.T) {
 	m := NewLatencyMap()
-	m.Add("foo", "", 0.1e9)
-	m.Add("foo", "", 0.2e9)
+	m.Add("foo", 0.1e9)
+	m.Add("foo", 0.2e9)
 
 	l := m.Latencies(1e-3)
 	if l["foo"] != 150 {

fuse/mountstate.go

@@ -152,11 +152,8 @@ func NewMountState(fs RawFileSystem) *MountState {
 	return ms
 }
 
-func (ms *MountState) Latencies() map[string]float64 {
-	if ms.latencies == nil {
-		return nil
-	}
-	return ms.latencies.Latencies(1e-3)
+func (ms *MountState) Latencies() *LatencyMap {
+	return ms.latencies
 }
 
 func (ms *MountState) OperationCounts() map[string]int {
@@ -220,6 +217,9 @@ func (ms *MountState) readRequest(exitIdle bool) (req *request, code Status) {
 		return nil, code
 	}
 
+	if ms.latencies != nil {
+		req.startNs = time.Now().UnixNano()
+	}
 	gobbled := req.setInput(dest[:n])
 
 	ms.reqMu.Lock()
@@ -259,14 +259,9 @@ func (ms *MountState) returnRequest(req *request) {
 
 func (ms *MountState) recordStats(req *request) {
 	if ms.latencies != nil {
-		endNs := time.Now().UnixNano()
-		dt := endNs - req.startNs
-
+		dt := time.Now().UnixNano() - req.startNs
 		opname := operationName(req.inHeader.Opcode)
-		ms.latencies.AddMany(
-			[]LatencyArg{
-				{opname, "", dt},
-				{opname + "-write", "", endNs - req.preWriteNs}})
+		ms.latencies.Add(opname, dt)
 	}
 }
 
@@ -302,9 +297,6 @@ exit:
 			break exit
 		}
 
-		if ms.latencies != nil {
-			req.startNs = time.Now().UnixNano()
-		}
 		ms.handleRequest(req)
 	}
 }
@@ -359,10 +351,6 @@ func (ms *MountState) write(req *request) Status {
 		log.Println(req.OutputDebug())
 	}
 
-	if ms.latencies != nil {
-		req.preWriteNs = time.Now().UnixNano()
-	}
-
 	if header == nil {
 		return OK
 	}