Add some performance tracing to the scanner

.vendor/src/github.com/rubyist/tracerx/README.md

@@ -18,6 +18,10 @@ tracerx.DefaultKey = "FOO"
 tracerx.Printf("send message")
 
 tracerx.PrintfKey("BAR", "do a thing")
+
+t := time.Now()
+// Do some stuff
+tracerx.PerformanceSince("BAR", "command x", t)
 ```
 
 This example will send tracing output based on the environment variables `FOO_TRACE` and `BAR_TRACE`.
@@ -31,6 +35,9 @@ absolute path:          output will be written to the file
 3 - 10:                 output will be written to that file descriptor
 ```
 
+If an associated `BAR_TRACE_PERFORMANCE` is set to 1 or "true", the `PerformanceSince` line will
+output timing information.
+
 Keys can also be disabled. See the GoDoc for full API documentation.
 
 ## Bugs, Issues, Feedback

.vendor/src/github.com/rubyist/tracerx/tracerx.go

@@ -14,6 +14,9 @@
 // By default, messages will be prefixed with "trace: ". This prefix can be
 // modified by setting Prefix.
 //
+// Each key can have an associated performance key, e.g. TRACERX_TRACE_PERFORMANCE.
+// If this key is 1 or "true" performance output will be written to the same output
+// as the tracing output.
 package tracerx
 
 import (
@@ -24,6 +27,7 @@ import (
 	"strconv"
 	"strings"
 	"sync"
+	"time"
 )
 
 var (
@@ -35,6 +39,7 @@ var (
 
 type tracer struct {
 	enabled     bool
+	performance bool
 	w           io.Writer
 }
 
@@ -45,19 +50,30 @@ func Printf(format string, args ...interface{}) {
 
 // PrintfKey writes a trace message for the given key
 func PrintfKey(key, format string, args ...interface{}) {
-	uppedKey := strings.ToUpper(key)
-
-	tracer, ok := tracers[uppedKey]
-	if !ok {
-		tracer = initializeTracer(uppedKey)
-	}
-
+	tracer := getTracer(key)
 	if tracer.enabled {
 		fmt.Fprintf(tracer.w, Prefix+format+"\n", args...)
 		return
 	}
 }
 
+// PerformanceSince writes out the time since the given time, if
+// tracing for the default key is enabled and the performance key is set
+func PerformanceSince(what string, t time.Time) {
+	PerformanceSinceKey(DefaultKey, what, t)
+}
+
+// PerformanceSince writes out the time since the given time, if
+// tracing for the given key is enabled and the performance key is set
+func PerformanceSinceKey(key, what string, t time.Time) {
+	tracer := getTracer(key)
+
+	if tracer.enabled && tracer.performance {
+		since := time.Since(t)
+		fmt.Fprintf(tracer.w, "performance %s: %.9f s\n", what, since.Seconds())
+	}
+}
+
 // Disable will disable tracing for the given key, regardless of
 // the environment variable
 func Disable(key string) {
@@ -76,15 +92,24 @@ func Enable(key string) {
 	}
 }
 
+func getTracer(key string) *tracer {
+	uppedKey := strings.ToUpper(key)
+	tracer, ok := tracers[uppedKey]
+	if !ok {
+		tracer = initializeTracer(uppedKey)
+	}
+	return tracer
+}
+
 func initializeTracer(key string) *tracer {
 	tracerLock.Lock()
 	defer tracerLock.Unlock()
 
 	if tracer, ok := tracers[key]; ok {
-		return tracer
+		return tracer // Someone else initialized while we were blocked
 	}
 
-	tracer := &tracer{false, os.Stderr}
+	tracer := &tracer{false, false, os.Stderr}
 	tracers[key] = tracer
 
 	trace := os.Getenv(fmt.Sprintf("%s_TRACE", key))
@@ -92,6 +117,11 @@ func initializeTracer(key string) *tracer {
 		return tracer
 	}
 
+	perf := os.Getenv(fmt.Sprintf("%s_TRACE_PERFORMANCE", key))
+	if perf == "1" || strings.ToLower(perf) == "true" {
+		tracer.performance = true
+	}
+
 	fd, err := strconv.Atoi(trace)
 	if err != nil {
 		// Not a number, it could be a path for a log file

Godeps

@@ -6,4 +6,4 @@ github.com/olekukonko/ts                      ecf753e7c962639ab5a1fb46f7da627d4c
 github.com/spf13/cobra                        864687ae689edc28688c67edef47e3d2ad651a1b
 github.com/spf13/pflag                        463bdc838f2b35e9307e91d480878bda5fff7232
 github.com/technoweenie/go-contentaddressable 38171def3cd15e3b76eb156219b3d48704643899
-github.com/rubyist/tracerx                    ecd28355a866ec2378f6df7d7cbf231141720e13
+github.com/rubyist/tracerx                    b869498bff1ad54bb2df3b98d11f3b6dcefbddc6

scanner/scanner.go

@@ -4,7 +4,9 @@ import (
 	"bytes"
 	"github.com/github/git-media/git"
 	"github.com/github/git-media/pointer"
+	"github.com/rubyist/tracerx"
 	"strconv"
+	"time"
 )
 
 type ScannedPointer struct {
@@ -17,14 +19,19 @@ func Scan(ref string) ([]*ScannedPointer, error) {
 
 	// Gets all objects git knows about
 	var buf bytes.Buffer
+	t := time.Now()
 	objects, _ := git.RevListObjects(ref, "", ref == "")
+	tracerx.PerformanceSince("rev-list --objects", t)
+
 	for _, o := range objects {
 		fileNameMap[o.Sha1] = o.Name
 		buf.WriteString(o.Sha1 + "\n")
 	}
 
 	// Get type and size info for all objects
+	t = time.Now()
 	objects, _ = git.CatFileBatchCheck(&buf)
+	tracerx.PerformanceSince("cat-file --batch-check", t)
 
 	// Pull out git objects that are type blob and size < 200 bytes.
 	// These are the likely git media pointer files
@@ -40,11 +47,14 @@ func Scan(ref string) ([]*ScannedPointer, error) {
 	// <sha1> <type> <size><LF>
 	// <contents><LF>
 	// This string contains all the data, so we parse it out below
+	t = time.Now()
 	data, _ := git.CatFileBatch(&mediaObjects)
+	tracerx.PerformanceSince("cat-file --batch", t)
 
 	r := bytes.NewBufferString(data)
 
 	pointers := make([]*ScannedPointer, 0)
+	t = time.Now()
 	for {
 		l, err := r.ReadBytes('\n')
 		if err != nil { // Probably check for EOF
@@ -73,5 +83,6 @@ func Scan(ref string) ([]*ScannedPointer, error) {
 			break
 		}
 	}
+	tracerx.PerformanceSince("decode pointers", t)
 	return pointers, nil
 }