github.com/onflow/flow-go@v0.35.7-crescendo-preview.23-atree-inlining/utils/binstat/binstat_external_test.go (about) 1 package binstat_test 2 3 import ( 4 "fmt" 5 "os" 6 "os/exec" 7 "regexp" 8 "runtime" 9 "runtime/pprof" 10 "strconv" 11 "sync" 12 "testing" 13 "time" 14 15 "github.com/rs/zerolog" 16 "github.com/stretchr/testify/require" 17 18 "github.com/onflow/flow-go/utils/binstat" 19 "github.com/onflow/flow-go/utils/unittest" 20 ) 21 22 /* 23 * NOTE: This command line can be used during binstat development to: 24 * 1. Run go fmt on the binstat .go files, and 25 * 2. Run the linter on the binstat .go files, and 26 * 3. Run the binstat tests with the full amount of logging (-v -vv), and 27 * 4. Turn JSON log line output with embedded \n into real new lines, and 28 * 5. Strip "time" field from JSON log line output for shorter read, and 29 * 6. Show the amount of code coverage from the tests. 30 * 31 * pushd utils/binstat ; go fmt ./*.go ; golangci-lint run && go test -v -vv -coverprofile=coverage.txt -covermode=atomic ./... | perl -lane 's~\\n~\n~g; s~"time".*?,~~g; print;' ; go tool cover -func=coverage.txt ; popd 32 */ 33 34 /* 35 * NOTE: The code below is inspired by the goroutine.go here [1] [2]. 36 * [1] https://eng.uber.com/pprof-go-profiler/ 37 * [2] https://github.com/chabbimilind/GoPprofDemo/blob/master/goroutine.go 38 */ 39 40 const loops = 2 41 const tries = 3 42 const funcs = 6 43 const mechs = 2 44 45 var wg sync.WaitGroup 46 var el [loops][tries][mechs][funcs]string 47 var zlog zerolog.Logger 48 49 // each function f1-f6 runs the same function f and adds its wall-clock execution time to a table of elapsed times 50 func f1(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 51 defer wg.Done() 52 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 53 } 54 func f2(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 55 defer wg.Done() 56 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 57 } 58 func f3(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 59 defer wg.Done() 60 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 61 } 62 func f4(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 63 defer wg.Done() 64 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 65 } 66 func f5(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 67 defer wg.Done() 68 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 69 } 70 func f6(outerFuncName string, f func(string) time.Duration, loop int, try int, i int) { 71 defer wg.Done() 72 el[loop][try][0][i] = fmt.Sprintf("%.02f", f(outerFuncName).Seconds()) 73 } 74 75 func run(t *testing.T, loop int, try int, gomaxprocs int) { 76 pprofFileName := fmt.Sprintf("binstat_external_test.loop-%d.try-%d.gomaxprocs-%d.pprof.txt", loop, try, gomaxprocs) 77 timerFile, err := os.Create(pprofFileName) 78 require.NoError(t, err) 79 80 require.NoError(t, pprof.StartCPUProfile(timerFile)) 81 82 // this function is purely for chewing CPU 83 f := func(outerFuncName string) time.Duration { 84 bs := binstat.EnterTime(outerFuncName) 85 var sum int 86 for i := 0; i < 10000000; i++ { 87 sum -= i / 2 88 sum *= i 89 sum /= i/3 + 1 90 sum -= i / 4 91 } 92 binstat.Debug(bs, fmt.Sprintf("%s() = %d", outerFuncName, sum)) 93 return binstat.Leave(bs) 94 } 95 96 runtime.GOMAXPROCS(gomaxprocs) 97 wg.Add(6) 98 go f1("~1f-via-f1", f, loop, try, 0) 99 go f2("~1f-via-f2", f, loop, try, 1) 100 go f3("~1f-via-f3", f, loop, try, 2) 101 go f4("~1f-via-f4", f, loop, try, 3) 102 go f5("~1f-via-f5", f, loop, try, 4) 103 go f6("~1f-via-f6", f, loop, try, 5) 104 105 wg.Wait() 106 pprof.StopCPUProfile() 107 require.NoError(t, timerFile.Close()) 108 109 // run pprof and capture its output 110 /* 111 e.g. $ go tool pprof -top -unit seconds binstat_external_test.loop-1.try-2.gomaxprocs-8.pprof.txt 2>&1 | egrep '(binstat_test.f|cum)' 112 e.g. flat flat% sum% cum cum% 113 e.g. 0 0% 100% 0.07s 19.44% github.com/onflow/flow-go/utils/binstat_test.f1 114 e.g. 0 0% 100% 0.02s 5.56% github.com/onflow/flow-go/utils/binstat_test.f2 115 e.g. 0 0% 100% 0.06s 16.67% github.com/onflow/flow-go/utils/binstat_test.f3 116 e.g. 0 0% 100% 0.11s 30.56% github.com/onflow/flow-go/utils/binstat_test.f4 117 e.g. 0 0% 100% 0.06s 16.67% github.com/onflow/flow-go/utils/binstat_test.f5 <-- NOTE: sometimes pprof fails to report a line?! 118 e.g. 0 0% 100% 0.03s 8.33% github.com/onflow/flow-go/utils/binstat_test.f6 119 */ 120 command := fmt.Sprintf("go tool pprof -top -unit seconds %s 2>&1 | egrep '(binstat_test.f|cum)'", pprofFileName) 121 out, err := exec.Command("bash", "-c", command).Output() 122 require.NoError(t, err) 123 //debug zlog.Debug().Msgf("test: output of command: %s\n%s", command, out) 124 125 // regex out the (cum)ulative column in pprof output, and the f<number> 126 r, _ := regexp.Compile(` ([0-9.]+)s.*\.f([0-9.]+)`) 127 matches := r.FindAllStringSubmatch(string(out), -1) 128 //debug zlog.Debug().Msgf("test: matches=%#v", matches) // e.g. matches=[][]string{[]string{\" 0.07s 20.59% github.com/onflow/flow-go/utils/binstat_test.f1\", \"0.07\", \"1\"}, []string{\" 0.04s 11.76% github.com/onflow/flow-go/utils/binstat_test.f2\", \"0.04\", \"2\"}, []string{\" 0.06s 17.65% github.com/onflow/flow-go/utils/binstat_test.f3\", \"0.06\", \"3\"}, []string{\" 0.05s 14.71% github.com/onflow/flow-go/utils/binstat_test.f4\", \"0.05\", \"4\"}, []string{\" 0.07s 20.59% github.com/onflow/flow-go/utils/binstat_test.f6\", \"0.07\", \"6\"}} 129 atLeast := funcs - 1 130 actual := len(matches) 131 require.Condition(t, func() bool { return actual >= atLeast }, "Unexpectedly few regex results on pprof output") 132 133 // add the regex matches to a table of elapsed times 134 for i := 0; i < len(matches); i++ { 135 //debug zlog.Debug().Msgf("test: matches[%d][1]=%s matches[%d][2]=%s", i, matches[i][1], i, matches[i][2]) 136 fi, err := strconv.Atoi(matches[i][2]) // 0-5 instead of 1-6 137 require.NoError(t, err) 138 require.Condition(t, func() bool { return (fi - 1) < funcs }, "f%d is not a value between 1 and %d", fi, funcs) 139 el[loop][try][1][fi-1] = matches[i][1] 140 } 141 } 142 143 func init() { 144 os.Setenv("BINSTAT_ENABLE", "1") 145 os.Setenv("BINSTAT_VERBOSE", "1") 146 os.Setenv("BINSTAT_LEN_WHAT", "~f=99;~eg=99;~example=99") 147 } 148 149 func backTicks(t *testing.T, command string) { 150 out, err := exec.Command("bash", "-c", command).Output() 151 require.NoError(t, err) 152 zlog.Debug().Msgf("test: output of command: %s\n%s", command, out) 153 } 154 155 func TestWithPprof(t *testing.T) { 156 zlog = unittest.Logger() 157 158 // delete any files hanging around from previous test run 159 backTicks(t, "ls -al ./binstat.test.pid-*.binstat.txt* ./*gomaxprocs*.pprof.txt ; rm -f ./binstat.test.pid-*.binstat.txt* ./*gomaxprocs*.pprof.txt") 160 161 // run the test; loops of several tries running groups of go-routines 162 for loop := 0; loop < loops; loop++ { 163 gomaxprocs := 8 164 if 0 == loop { 165 gomaxprocs = 1 166 } 167 bs := binstat.EnterTime(fmt.Sprintf("loop-%d", loop)) 168 for try := 0; try < tries; try++ { 169 zlog.Debug().Msgf("test: loop=%d try=%d; running 6 identical functions with gomaxprocs=%d", loop, try+1, gomaxprocs) 170 run(t, loop, try, gomaxprocs) 171 } 172 binstat.Leave(bs) 173 } 174 175 // output a table of results similar to this 176 /* 177 - binstat------- pprof--------- 178 - try1 try2 try3 try1 try2 try3 179 - 0.29 0.30 0.29 0.05 0.03 0.05 // f1() seconds; loop=0 gomaxprocs=1 180 - 0.35 0.30 0.35 0.07 0.06 0.06 // f2() seconds; loop=0 gomaxprocs=1 181 - 0.28 0.33 0.28 0.06 0.06 0.06 // f3() seconds; loop=0 gomaxprocs=1 182 - 0.31 0.28 0.31 0.05 0.06 0.06 // f4() seconds; loop=0 gomaxprocs=1 183 - 0.27 0.28 0.27 0.05 0.05 0.05 // f5() seconds; loop=0 gomaxprocs=1 184 - 0.38 0.38 0.39 0.06 0.05 0.06 // f6() seconds; loop=0 gomaxprocs=1 185 - binstat------- pprof--------- 186 - try1 try2 try3 try1 try2 try3 187 - 0.07 0.07 0.07 0.05 0.03 0.07 // f1() seconds; loop=1 gomaxprocs=8 188 - 0.07 0.07 0.07 0.05 0.04 0.03 // f2() seconds; loop=1 gomaxprocs=8 189 - 0.07 0.07 0.07 0.04 0.07 0.07 // f3() seconds; loop=1 gomaxprocs=8 190 - 0.07 0.07 0.07 0.05 0.02 0.08 // f4() seconds; loop=1 gomaxprocs=8 191 - 0.07 0.07 0.07 0.09 0.06 0.07 // f5() seconds; loop=1 gomaxprocs=8 192 - 0.07 0.07 0.07 0.04 0.10 0.03 // f6() seconds; loop=1 gomaxprocs=8 193 */ 194 for loop := 0; loop < loops; loop++ { 195 zlog.Debug().Msg("test: binstat------- pprof---------") 196 l1 := "test:" 197 for r := 0; r < 2; r++ { 198 for try := 0; try < tries; try++ { 199 l1 = l1 + fmt.Sprintf(" try%d", try+1) 200 } 201 } 202 zlog.Debug().Msg(l1) 203 gomaxprocs := 8 204 if 0 == loop { 205 gomaxprocs = 1 206 } 207 for i := 0; i < funcs; i++ { 208 l2 := "test:" 209 for mech := 0; mech < mechs; mech++ { 210 for try := 0; try < tries; try++ { 211 l2 = l2 + fmt.Sprintf(" %s", el[loop][try][mech][i]) 212 } 213 } 214 l2 = l2 + fmt.Sprintf(" // f%d() seconds; loop=%d gomaxprocs=%d", i+1, loop, gomaxprocs) 215 zlog.Debug().Msg(l2) 216 } 217 } 218 219 // tell binstat to close down and write its stats file one last time 220 binstat.Dump(".test-external.txt") 221 222 // cat and sort binstat stats file 223 backTicks(t, "ls -al ./binstat.test.pid-*.binstat.txt ; cat ./binstat.test.pid-*.binstat.txt.test-external.txt | sort --version-sort") 224 225 // todo: add more tests? which tests? 226 227 // if we get here then no require.NoError() calls kicked in :-) 228 } 229 230 func grepOutputFileAndSanatize(file string, what string) []byte { 231 binstat.Dump(file) // skip waiting for dump at next wallclock second 232 cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what) 233 out, err := exec.Command("bash", "-c", cmd).CombinedOutput() 234 if err != nil { 235 panic(err) 236 } 237 return out 238 } 239 240 func ExampleEnter() { 241 bs := binstat.Enter("~7exampleEnter") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 242 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here 243 fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter.txt", "exampleEnter")) // force binstat output & grep & sanitize line; digits to <num> so example test passes 244 // Output: /GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnter]=<num> <num> // e.g. utils/binstat_test.ExampleEnter:<num> 245 } 246 247 func ExampleEnterVal() { 248 bs := binstat.EnterVal("~7exampleEnterVal", 123) // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 249 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here, (c) creates "/size[<num>-<num>]=<num>" bin section 250 fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-val.txt", "exampleEnterVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes 251 // Output: /GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterVal]/size[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterVal:<num> 252 } 253 254 func ExampleEnterTime() { 255 bs := binstat.EnterTime("~7exampleEnterTime") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 256 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here, (c) creates "/time[<num>-<num>]" bin section 257 fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-time.txt", "exampleEnterTime")) // force binstat output & grep & sanitize line; digits to <num> so example test passes 258 // Output: /GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterTime]/time[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterTime:<num> 259 } 260 261 func ExampleEnterTimeVal() { 262 bs := binstat.EnterTimeVal("~7exampleEnterTimeVal", 123) // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 263 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here, (c) creates "/time[<num>-<num>]" bin section, (d) creates "/size[<num>-<num>]=<num>" bin section 264 fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-time-val.txt", "exampleEnterTimeVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes 265 // Output: /GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterTimeVal]/size[<num>-<num>]/time[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterTimeVal:<num> 266 } 267 268 func ExampleLeaveVal() { 269 bs := binstat.Enter("~7exampleLeaveVal") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 270 binstat.LeaveVal(bs, 123) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here, (c) creates "/size[<num>-<num>]=<num>" bin section 271 fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-leave-val.txt", "exampleLeaveVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes 272 // Output: /GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleLeaveVal]/size[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleLeaveVal:<num> 273 } 274 275 // .Debug() only used for debugging binstat 276 func ExampleDebug() { 277 bs := binstat.Enter("~7exampleDebug") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 278 binstat.Debug(bs, "hello world") // only for binstat debbuging, and enabled if env var BINSTAT_VERBOSE set 279 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here 280 // e.g. STDOUT: {"level":"debug","message":"2.918396 71372=pid 18143200=tid utils/binstat_test.ExampleBinStat_Debug:301() // enter in 0.000044 // what[~7exampleDebug] .NumCPU()=8 .GOMAXPROCS(0)=8 .NumGoroutine()=3"} 281 // e.g. STDOUT: {"level":"debug","message":"2.918504 71372=pid 18143200=tid utils/binstat_test.ExampleBinStat_Debug:301() // debug hello world"} 282 // e.g. STDOUT: {"level":"debug","message":"2.918523 71372=pid 18143200=tid utils/binstat_test.ExampleBinStat_Debug:301() // leave in 0.000168 // /GOMAXPROCS=8,CPUS=8/what[~7exampleDebug]=[47]=1 0.000053"} 283 fmt.Printf("debug via STDOUT only") 284 // Output: debug via STDOUT only 285 } 286 287 // .DebugParams() only used for debugging binstat 288 func ExampleDebugParams() { 289 bs := binstat.Enter("~7exampleDebug") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99") 290 binstat.DebugParams(bs, "foo=1") // only for debbuging, and enabled if env var BINSTAT_VERBOSE set; used to add string representing parameters to debug output 291 binstat.Debug(bs, "hello world") // only for debbuging, and enabled if env var BINSTAT_VERBOSE set 292 binstat.Leave(bs) // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here 293 // e.g. STDOUT: {"level":"debug","message":"2.758196 72784=pid 18162115=tid utils/binstat_test.ExampleBinStat_DebugParams:314() // enter in 0.000015 // what[~7exampleDebug] .NumCPU()=8 .GOMAXPROCS(0)=8 .NumGoroutine()=3"} 294 // e.g. STDOUT: {"level":"debug","message":"2.758255 72784=pid 18162119=tid utils/binstat_test.ExampleBinStat_DebugParams:314(foo=1) // debug hello world"} 295 // e.g. STDOUT: {"level":"debug","message":"2.758447 72784=pid 18162119=tid utils/binstat_test.ExampleBinStat_DebugParams:314(foo=1) // leave in 0.000256 // /GOMAXPROCS=8,CPUS=8/what[~7exampleDebug]=[51]=2 0.000306"} 296 fmt.Printf("debug via STDOUT only") 297 // Output: debug via STDOUT only 298 }