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  }