Add first access analysis (#165)

This will print out the request stats for the first object access in case the same object is accessed more than once (typically in GET operations)

Example output single sized objects:

```
Requests considered: 4737:
 * Avg: 5.323s, 50%: 4.499s, 90%: 9.432s, 99%: 15.234s, Fastest: 499ms, Slowest: 23.375s
 * First Byte: Avg: 747ms, Median: 458ms, Best: 17ms, Worst: 7.613s
 * First Access:
         - Avg: 5.561s, 50%: 4.762s, 90%: 9.58s, 99%: 15.441s, Fastest: 957ms, Slowest: 23.375s
         - TTFB: Avg: 984ms, Median: 662ms, Best: 59ms, Worst: 7.613s
```

Multi sized:
```
Requests considered: 77861. Multiple sizes, average 1833115 bytes:

Request size 1 B -> 10 KiB. Requests - 10811:
 * Throughput: Average: 1534.1KiB/s, 50%: 1571.1KiB/s, 90%: 163.3KiB/s, 99%: 6.6KiB/s, Fastest: 9.7MiB/s, Slowest: 1124.8B/s
 * First Byte: Avg: 3ms, Median: 2ms, Best: 1ms, Worst: 39ms
 * First Access: Average: 4.6MiB/s, 50%: 4.5MiB/s, 90%: 979.4KiB/s, 99%: 67.4KiB/s, Fastest: 9.7MiB/s, Slowest: 8.8KiB/s
 * First Access TTFB: Avg: 1ms, Median: 1ms, Best: 1ms, Worst: 2ms

Request size 10KiB -> 1MiB. Requests - 38069:
 * Throughput: Average: 73.5MiB/s, 50%: 66.4MiB/s, 90%: 27.0MiB/s, 99%: 13.6MiB/s, Fastest: 397.6MiB/s, Slowest: 3.1MiB/s
 * First Byte: Avg: 3ms, Median: 2ms, Best: 1ms, Worst: 41ms
 * First Access: Average: 152.4MiB/s, 50%: 138.3MiB/s, 90%: 69.8MiB/s, 99%: 42.5MiB/s, Fastest: 397.6MiB/s, Slowest: 39.1MiB/s
 * First Access TTFB: Avg: 1ms, Median: 1ms, Best: 1ms, Worst: 3ms

Request size 1MiB -> 10MiB. Requests - 32992:
 * Throughput: Average: 162.1MiB/s, 50%: 159.4MiB/s, 90%: 114.3MiB/s, 99%: 80.3MiB/s, Fastest: 505.4MiB/s, Slowest: 22.4MiB/s
 * First Byte: Avg: 3ms, Median: 2ms, Best: 1ms, Worst: 40ms
 * First Access: Average: 273.0MiB/s, 50%: 265.4MiB/s, 90%: 217.7MiB/s, 99%: 189.8MiB/s, Fastest: 505.4MiB/s, Slowest: 166.7MiB/s
 * First Access TTFB: Avg: 2ms, Median: 2ms, Best: 1ms, Worst: 15ms
```

cli/analyze.go

@@ -442,18 +442,35 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo
 			return
 		}
 
-		console.Println(
-			" * Avg:", time.Duration(reqs.DurAvgMillis)*time.Millisecond,
-			"50%:", time.Duration(reqs.DurMedianMillis)*time.Millisecond,
-			"90%:", time.Duration(reqs.Dur90Millis)*time.Millisecond,
-			"99%:", time.Duration(reqs.Dur99Millis)*time.Millisecond,
-			"Fastest:", time.Duration(reqs.FastestMillis)*time.Millisecond,
-			"Slowest:", time.Duration(reqs.SlowestMillis)*time.Millisecond,
-		)
+		console.Print(
+			" * Avg: ", time.Duration(reqs.DurAvgMillis)*time.Millisecond,
+			", 50%: ", time.Duration(reqs.DurMedianMillis)*time.Millisecond,
+			", 90%: ", time.Duration(reqs.Dur90Millis)*time.Millisecond,
+			", 99%: ", time.Duration(reqs.Dur99Millis)*time.Millisecond,
+			", Fastest: ", time.Duration(reqs.FastestMillis)*time.Millisecond,
+			", Slowest: ", time.Duration(reqs.SlowestMillis)*time.Millisecond,
+			"\n")
 
 		if reqs.FirstByte != nil {
 			console.Println(" * First Byte:", reqs.FirstByte)
 		}
+
+		if reqs.FirstAccess != nil {
+			reqs := reqs.FirstAccess
+			console.Print(
+				" * First Access: Avg: ", time.Duration(reqs.DurAvgMillis)*time.Millisecond,
+				", 50%: ", time.Duration(reqs.DurMedianMillis)*time.Millisecond,
+				", 90%: ", time.Duration(reqs.Dur90Millis)*time.Millisecond,
+				", 99%: ", time.Duration(reqs.Dur99Millis)*time.Millisecond,
+				", Fastest: ", time.Duration(reqs.FastestMillis)*time.Millisecond,
+				", Slowest: ", time.Duration(reqs.SlowestMillis)*time.Millisecond,
+				"\n")
+			if reqs.FirstByte != nil {
+				console.Print(" * First Access TTFB: ", reqs.FirstByte)
+			}
+			console.Println("")
+		}
+
 		if eps := reqs.ByHost; len(eps) > 1 && details {
 			console.SetColor("Print", color.New(color.FgHiWhite))
 			console.Println("\nRequests by host:")
@@ -504,9 +521,26 @@ func printRequestAnalysis(ctx *cli.Context, ops aggregate.Operation, details boo
 			", Fastest: ", bench.Throughput(s.BpsFastest),
 			", Slowest: ", bench.Throughput(s.BpsSlowest),
 			"\n")
+
 		if s.FirstByte != nil {
 			console.Println(" * First Byte:", s.FirstByte)
 		}
+
+		if s.FirstAccess != nil {
+			s := s.FirstAccess
+			console.Print(""+
+				" * First Access: Average: ", bench.Throughput(s.BpsAverage),
+				", 50%: ", bench.Throughput(s.BpsMedian),
+				", 90%: ", bench.Throughput(s.Bps90),
+				", 99%: ", bench.Throughput(s.Bps99),
+				", Fastest: ", bench.Throughput(s.BpsFastest),
+				", Slowest: ", bench.Throughput(s.BpsSlowest),
+				"\n")
+			if s.FirstByte != nil {
+				console.Print(" * First Access TTFB: ", s.FirstByte, "\n")
+			}
+		}
+
 	}
 	if eps := reqs.ByHost; len(eps) > 1 && details {
 		console.SetColor("Print", color.New(color.FgHiWhite))

pkg/aggregate/requests.go

@@ -46,6 +46,9 @@ type SingleSizedRequests struct {
 	SlowestMillis int `json:"slowest_millis"`
 	// Time to first byte if applicable.
 	FirstByte *TTFB `json:"first_byte,omitempty"`
+	// FirstAccess is filled if the same object is accessed multiple times.
+	// This records the first touch of the object.
+	FirstAccess *SingleSizedRequests `json:"first_access,omitempty"`
 	// Request times by host.
 	ByHost map[string]SingleSizedRequests `json:"by_host,omitempty"`
 }
@@ -64,6 +67,16 @@ func (a *SingleSizedRequests) fill(ops bench.Operations) {
 	a.FirstByte = TtfbFromBench(ops.TTFB(start, end))
 }
 
+func (a *SingleSizedRequests) fillFirst(ops bench.Operations) {
+	if !ops.IsMultiTouch() {
+		return
+	}
+	r := SingleSizedRequests{}
+	ops = ops.FilterFirst()
+	r.fill(ops)
+	a.FirstAccess = &r
+}
+
 type RequestSizeRange struct {
 	// Number of requests in this range.
 	Requests int `json:"requests"`
@@ -85,6 +98,10 @@ type RequestSizeRange struct {
 	BpsFastest float64 `json:"bps_fastest"`
 	BpsSlowest float64 `json:"bps_slowest"`
 
+	// FirstAccess is filled if the same object is accessed multiple times.
+	// This records the first touch of the object.
+	FirstAccess *RequestSizeRange `json:"first_access,omitempty"`
+
 	// Time to first byte if applicable.
 	FirstByte *TTFB `json:"first_byte,omitempty"`
 }
@@ -105,6 +122,18 @@ func (r *RequestSizeRange) fill(s bench.SizeSegment) {
 	r.BpsSlowest = s.Ops.Median(1).BytesPerSec().Float()
 }
 
+func (r *RequestSizeRange) fillFirst(s bench.SizeSegment) {
+	if !s.Ops.IsMultiTouch() {
+		return
+	}
+	s.Ops = s.Ops.FilterFirst()
+	a := RequestSizeRange{}
+	a.fill(s)
+	a.FirstByte = TtfbFromBench(s.Ops.TTFB(s.Ops.TimeRange()))
+
+	r.FirstAccess = &a
+}
+
 // MultiSizedRequests contains statistics when objects have the same different size.
 type MultiSizedRequests struct {
 	// Skipped if too little data.
@@ -139,6 +168,7 @@ func (a *MultiSizedRequests) fill(ops bench.Operations) {
 			s := sizes[i]
 			var r RequestSizeRange
 			r.fill(s)
+			r.fillFirst(s)
 			r.FirstByte = TtfbFromBench(s.Ops.TTFB(start, end))
 			// Store
 			a.BySize[i] = r
@@ -160,6 +190,7 @@ func RequestAnalysisSingleSized(o bench.Operations, allThreads bool) *SingleSize
 		return &res
 	}
 	res.fill(active)
+	res.fillFirst(o)
 	res.ByHost = RequestAnalysisHostsSingleSized(o)
 
 	return &res

pkg/aggregate/ttfb.go

@@ -37,7 +37,7 @@ func (t TTFB) String() string {
 	if t.AverageMillis == 0 {
 		return ""
 	}
-	return fmt.Sprintf("Average: %v, Median: %v, Best: %v, Worst: %v",
+	return fmt.Sprintf("Avg: %v, Median: %v, Best: %v, Worst: %v",
 		time.Duration(t.AverageMillis)*time.Millisecond,
 		time.Duration(t.MedianMillis)*time.Millisecond,
 		time.Duration(t.FastestMillis)*time.Millisecond,

pkg/bench/ops.go

@@ -431,6 +431,18 @@ func (o Operations) IsMixed() bool {
 	return o.isMixed(o.OpTypes())
 }
 
+// IsMultiTouch returns true if the same files are touched multiple times.
+func (o Operations) IsMultiTouch() bool {
+	seen := make(map[string]struct{}, len(o))
+	for _, op := range o {
+		if _, ok := seen[op.File]; ok {
+			return true
+		}
+		seen[op.File] = struct{}{}
+	}
+	return false
+}
+
 // HasError returns whether one or more operations failed.
 func (o Operations) HasError() bool {
 	if len(o) == 0 {
@@ -883,6 +895,24 @@ func (o Operations) FilterSuccessful() Operations {
 	return ok
 }
 
+// FilterFirst returns the first operation on any file.
+func (o Operations) FilterFirst() Operations {
+	if len(o) == 0 {
+		return nil
+	}
+	ok := make(Operations, 0, 1000)
+	seen := make(map[string]struct{}, len(o))
+	for _, op := range o {
+		if _, ok := seen[op.File]; ok {
+			continue
+		}
+		seen[op.File] = struct{}{}
+		ok = append(ok, op)
+	}
+
+	return ok
+}
+
 // Errors returns the errors found.
 func (o Operations) FilterErrors() Operations {
 	if len(o) == 0 {
@@ -956,6 +986,22 @@ func OperationsFromCSV(r io.Reader, analyzeOnly bool, offset, limit int, log fun
 		cb++
 		return clientMap[c]
 	}
+	var fileMap = func(s string) string {
+		return s
+	}
+	if analyzeOnly {
+		// When analyzing map file names to a number for less RAM.
+		var i int
+		m := make(map[string]int)
+		fileMap = func(s string) string {
+			if v, ok := m[s]; ok {
+				return strconv.Itoa(v)
+			}
+			i++
+			m[s] = i
+			return strconv.Itoa(i)
+		}
+	}
 	for {
 		values, err := cr.Read()
 		if err == io.EOF {
@@ -1006,10 +1052,8 @@ func OperationsFromCSV(r io.Reader, analyzeOnly bool, offset, limit int, log fun
 		if idx, ok := fieldIdx["client_id"]; ok {
 			clientID = values[idx]
 		}
-		var file string
-		if !analyzeOnly {
-			file = values[fieldIdx["file"]]
-		}
+		file := fileMap(values[fieldIdx["file"]])
+
 		ops = append(ops, Operation{
 			OpType:    values[fieldIdx["op"]],
 			ObjPerOp:  int(objs),