More debugging perf stats

2 files changed, 47 insertions, 29 deletions

diff --git a/debugon.go b/debugon.go
index 56698db..f194bbc 100644
--- a/debugon.go
+++ b/debugon.go
@@ -21,12 +21,15 @@ var activeParsers []*debugParser
 var longestLocation = 0
 
 type debugParser struct {
-	Match    string
-	Var      string
-	Location string
-	Next     Parser
-	Time     time.Duration
-	Calls    int
+	Match      string
+	Var        string
+	Location   string
+	Next       Parser
+	Cumulative time.Duration
+	Self       time.Duration
+	SelfStart  time.Time
+	Calls      int
+	Errors     int
 }
 
 func (dp *debugParser) Name() string {
@@ -77,13 +80,18 @@ func (dp *debugParser) logEnd(ps *State, result *Result) {
 func (dp *debugParser) Parse(ps *State) Result {
 	activeParsers = append(activeParsers, dp)
 	start := time.Now()
+	dp.SelfStart = start
 
 	dp.logStart(ps)
 	ret := dp.Next(ps)
 	dp.logEnd(ps, &ret)
 
-	dp.Time = dp.Time + time.Since(start)
+	dp.Cumulative += time.Since(start)
+	dp.Self += time.Since(dp.SelfStart)
 	dp.Calls++
+	if ps.Errored() {
+		dp.Errors++
+	}
 
 	activeParsers = activeParsers[0 : len(activeParsers)-1]
 	return ret
@@ -99,7 +107,15 @@ func NewParser(name string, p Parser) Parser {
 		Match:    name,
 		Var:      description,
 		Location: location,
-		Next:     p,
+	}
+
+	dp.Next = func(ps *State) Result {
+		dp.Self += time.Since(dp.SelfStart)
+
+		ret := p(ps)
+
+		dp.SelfStart = time.Now()
+		return ret
 	}
 
 	if len(dp.Location) > longestLocation {
@@ -123,11 +139,12 @@ func DisableLogging() {
 // DumpDebugStats will print out the curring timings for each parser if built with -tags debug
 func DumpDebugStats() {
 	sort.Slice(parsers, func(i, j int) bool {
-		return parsers[i].Time >= parsers[j].Time
+		return parsers[i].Self >= parsers[j].Self
 	})
 
 	fmt.Println("Parser stats:")
+	fmt.Println("      var name           matches               total time        self time           calls           errors      location  ")
 	for _, parser := range parsers {
-		fmt.Printf("%20s\t%10s\t%10d\tcalls\t%s\n", parser.Name(), parser.Time.String(), parser.Calls, parser.Location)
+		fmt.Printf("%20s  %20s  %15s  %15s  %10d calls  %10d errors %s\n", parser.Var, parser.Match, parser.Cumulative.String(), parser.Self.String(), parser.Calls, parser.Errors, parser.Location)
 	}
 }
diff --git a/readme.md b/readme.md
index e285701..f4af219 100644
--- a/readme.md
+++ b/readme.md
@@ -85,25 +85,26 @@ ok      github.com/vektah/goparsify/html        0.118s
 ### debugging performance
 If you build the parser with -tags debug it will instrument each parser and a call to DumpDebugStats() will show stats:
 ```
-              _value    12.6186996s        2618801      calls   json.go:36
-             _object    9.0349494s          361213      calls   json.go:24
-         _properties    8.9393995s          361213      calls   json.go:14
-         _properties    8.5702176s         2438185      calls   json.go:14
-              _array    2.3471541s          391315      calls   json.go:16
-              _array     2.263117s           30102      calls   json.go:16
-         _properties    257.1277ms         2438185      calls   json.go:14
-             _string    165.0818ms         2528489      calls   json.go:12
-         _properties     94.0519ms         2438185      calls   json.go:14
-               _true     81.5423ms         2618798      calls   json.go:10
-              _false      74.032ms         2558593      calls   json.go:11
-               _null     70.0318ms         2618801      calls   json.go:9
-         _properties     56.5289ms         2438185      calls   json.go:14
-             _number     52.0277ms          933135      calls   json.go:13
-              _array      20.008ms          391315      calls   json.go:16
-             _object     17.5049ms          361213      calls   json.go:24
-             _object      9.0073ms          361213      calls   json.go:24
-              _array      3.0025ms          150509      calls   json.go:16
-              _array      3.0019ms           30102      calls   json.go:16
+      var name           matches               total time        self time           calls           errors      location
+              _value                 Any()       6.3303551s        46.0214ms      878801 calls           0 errors json.go:36
+             _string        string literal       100.0559ms         44.019ms      848489 calls      313135 errors json.go:12
+              _false                 false        52.0288ms        43.0197ms      858593 calls      848489 errors json.go:11
+               _null                  null        58.0309ms        42.0222ms      878801 calls      878798 errors json.go:9
+         _properties        string literal       119.3651ms        42.0151ms      818185 calls           0 errors json.go:14
+         _properties                     :        54.5277ms         41.018ms      818185 calls           0 errors json.go:14
+               _true                  true        56.5292ms        37.0166ms      878798 calls      858593 errors json.go:10
+         _properties                 Seq()       4.2989722s        35.5217ms      818185 calls           0 errors json.go:14
+         _properties                     ,        45.0263ms         35.519ms      818185 calls      121213 errors json.go:14
+             _number        number literal        30.0208ms        11.5093ms      313135 calls      131315 errors json.go:13
+              _array                     [        12.0045ms         10.504ms      131315 calls      121213 errors json.go:16
+         _properties                Some()       4.4800665s         9.0051ms      121213 calls           0 errors json.go:14
+             _object                     {        11.0053ms         8.5041ms      121213 calls           0 errors json.go:24
+             _object                     }         9.0022ms         8.0031ms      121213 calls           0 errors json.go:24
+             _object                 Seq()       4.5375994s         6.5055ms      121213 calls           0 errors json.go:24
+              _array                 Seq()       1.1524115s         5.5023ms      131315 calls      121213 errors json.go:16
+              _array                     ,         3.0008ms         4.0012ms       50509 calls       10102 errors json.go:16
+              _array                     ]         1.5013ms         1.5011ms       10102 calls           0 errors json.go:16
+              _array                Some()        1.116393s               0s       10102 calls           0 errors json.go:16
 ```
 All times are cumulative, it would be nice to break this down into a parse tree with relative times. This is a nice addition to pprof as it will break down the parsers based on where they are used instead of grouping them all by type.