From e30b92276464f1a7cbd9e3772f315c990fac2073 Mon Sep 17 00:00:00 2001 From: Adam Scarr Date: Sun, 13 Aug 2017 14:08:21 +1000 Subject: [PATCH] More debugging perf stats --- debugon.go | 37 +++++++++++++++++++++++++++---------- readme.md | 39 ++++++++++++++++++++------------------- 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.