binstat

package
v0.27.0-pre-release-1 Latest Latest
Warning

This package is not in the latest version of its module.

 Go to latest Published: Jul 22, 2022 License: AGPL-3.0 Imports: 12 Imported by: 0

README

binstat - run-time & space efficient stats in bins

Why use binstat?

  • pprof reports the seconds of CPU used and not the seconds of wall-clock used.
  • trace can be too heavyweight for larger Golang programs.
  • prometheus can be heavyweight, and it's difficult to programmatically manage stats once exported.
  • logging can be heavyweight; 1M function calls == 1M log lines.

binstat goals

  • binstat is disabled at compile time by default resulting in zero production code overhead.
  • binstat may be enabled at compile time on a stat by stat basis without enabling all stats.
  • binstat aims to be efficient at collecting small stats very fast, e.g. measuring lock time.
  • binstat aims to allow stats to be compared programmatically; is this worse/better than last run?

How binstat works?

  • Sprinkle binstat.Enter*(<what>) and binstat.Leave*() into Golang source code, e.g.:
import (
...
	"github.com/onflow/flow-go/utils/binstat"
...
)
...
	for loop := 0; loop < 2; loop++ {
		bs := binstat.EnterTime(fmt.Sprintf("loop-%d", loop))
		myFunc() // code to generate stats for
		binstat.Leave(bs)
	}
  • Run the program, and max. once per second a stats file will be written opportunistically, e.g.:
$ cat myproc.pid-085882.txt| egrep loop
/GOMAXPROCS=1,GC=100/what[loop-0]/time[1.000000-1.999999]=1 1.912292 // e.g. mypkg.myFunc:161
/GOMAXPROCS=8,GC=100/what[loop-1]/time[0.600000-0.699999]=1 0.696432 // e.g. mypkg.myFunc:161
$ #   user defined string ^^^^^^
$ #          bin time range in seconds ^^^^^^^^^^^^^^^^^
$ #                                 times bin incremented ^
$ #                        total seconds for all increments ^^^^^^^^
$ #                                         name & line of instrumented file ^^^^^^^^^^^^^^^^
  • If myFunc() is identical, why different results? E.g. launches 3 go-routines executing slower if GOMAXPROCS=1.
How 'collapsable' <what> works?
  • If <what> has the format ~<default len><what>, then ~4RootL1L2 only uses ~4Root in the bin name, unless env var BINSTAT_LEN_WHAT="~Root=6" in which case the bin name uses ~4RootL1.
  • In this way, the bin quantity for a particular <what> defaults to fewer bins, but may be enlarged using the env var.

Disable AKA 'hide' binstat instrumentation before pushing code

$ utils/binstat/binstat                     
utils/binstat/binstat: Please specifiy a command line option: (list|hide|unhide)-instrumentation [regex='binstat.Bin(Net|MakeID)']
$ utils/binstat/binstat hide-instrumentation
- hide instrumentation found 17 files to examine <-- source files containing binstat instrumentation
- hide instrumentation wrote 0 files             <-- source files rewritten with commented binstat
  • Auto commented binstat code looks like this:
import (
...
	_ "github.com/onflow/flow-go/utils/binstat"
...
)
...
	for loop := 0; loop < 2; loop++ {
		//bs := binstat.EnterTime(fmt.Sprintf("loop-%d", loop))
		myFunc() // code to generate stats for
		//binstat.Leave(bs)
	}

What makes binstat efficient?

  • The number of bins is relatively small, regardless of the number of function calls.
  • For timing, binstat uses runtime.nano() which is used by & about twice as fast as time.Now().
  • A lock per stat collection is eliminated using a sync.RWMutex{} reader/writer mutual exclusion lock:
    • Usual case: If the bin already exists, any 'reader' can concurrently update it via atomic operations.
    • Rare event: Else a single 'writer' blocks all 'readers' to add the new bin.
  • binstat instrumentation can be disabled in two different ways:
    • At compile time via source code commenting of instrumentation.
    • At run-time if BINSTAT_ENABLE does not exist.

Example comparison with pprof

  • This example -- on a GCP Linux box -- launches 6 identical go-routines, 3 times, with gomaxprocs=1 & then =8.
$ pushd binstat ; go test -v -vv ./... 2>&1 | perl -lane 's~\\n~\n~g; s~"time".*?,~~g; print;' ; popd
...
=== RUN   TestWithPprof
...
{"level":"debug","message":"test: loop=0 try=1; running 6 identical functions with gomaxprocs=1"}
...
{"level":"debug","message":"test: loop=0 try=2; running 6 identical functions with gomaxprocs=1"}
...
{"level":"debug","message":"test: loop=0 try=3; running 6 identical functions with gomaxprocs=1"}
...
{"level":"debug","message":"test: loop=1 try=1; running 6 identical functions with gomaxprocs=8"}
...
{"level":"debug","message":"test: loop=1 try=2; running 6 identical functions with gomaxprocs=8"}
...
{"level":"debug","message":"test: loop=1 try=3; running 6 identical functions with gomaxprocs=8"}
...
  • The test collects running times from binstat & pprof for a side by side comparison.
    • Note: With gomaxprocs=1 there is a large delta between CPU & wall-clock, e.g. 0.07 vs 0.40 seconds.
    • Note: With gomaxprocs=8 pprof CPU time incorrectly varies between 0.02 to 0.12 seconds.
{"level":"debug","message":"test: binstat------- pprof---------"}
{"level":"debug","message":"test: try1 try2 try3 try1 try2 try3"}
{"level":"debug","message":"test: 0.38 0.40 0.38 0.06 0.06 0.05 // f1() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: 0.37 0.38 0.36 0.06 0.07 0.06 // f2() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: 0.29 0.37 0.34 0.06 0.06 0.06 // f3() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: 0.33 0.35 0.32 0.06 0.07 0.06 // f4() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: 0.28 0.34 0.29 0.05 0.06 0.06 // f5() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: 0.40 0.40 0.36 0.06 0.05 0.06 // f6() seconds; loop=0 gomaxprocs=1"}
{"level":"debug","message":"test: binstat------- pprof---------"}
{"level":"debug","message":"test: try1 try2 try3 try1 try2 try3"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.04 0.05 0.07 // f1() seconds; loop=1 gomaxprocs=8"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.05 0.07 0.05 // f2() seconds; loop=1 gomaxprocs=8"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.06 0.11 0.02 // f3() seconds; loop=1 gomaxprocs=8"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.06 0.06 0.06 // f4() seconds; loop=1 gomaxprocs=8"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.09 0.05 0.04 // f5() seconds; loop=1 gomaxprocs=8"}
{"level":"debug","message":"test: 0.07 0.08 0.07 0.03 0.04 0.12 // f6() seconds; loop=1 gomaxprocs=8"}
  • Finally, the test shows the binstat sorted file containing the stats.
  • This part is when GOMAXPROCS=1.
    • Note: The binstat.tck bins show how many 1/10ths of a second had how many go-routines running.
    • Note: The binstat.dmp bins show how long opportunistically saving the binstat file took.
{"level":"debug","message":"test: output of command: ls -al ./binstat.test.pid-*.binstat.txt ; cat ./binstat.test.pid-*.binstat.txt | sort --version-sort
-rw-r--r--  1 simonhardy-francis  staff  3610 23 Jun 17:10 ./binstat.test.pid-047616.binstat.txt
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f1]/time[0.200000-0.299999]=1 0.292582 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f1]/time[0.300000-0.399999]=2 0.758238 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f2]/time[0.200000-0.299999]=2 0.587235 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f2]/time[0.300000-0.399999]=1 0.356942 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f3]/time[0.300000-0.399999]=3 1.017089 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f4]/time[0.200000-0.299999]=2 0.562171 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f4]/time[0.300000-0.399999]=1 0.315660 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f5]/time[0.200000-0.299999]=2 0.567996 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f5]/time[0.300000-0.399999]=1 0.301534 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[~1f-via-f6]/time[0.300000-0.399999]=3 1.157075 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=1,CPUS=8/what[internal-NumG]/size[4]=6 0.000185 // e.g. utils/binstat.tick:424
/GOMAXPROCS=1,CPUS=8/what[internal-NumG]/size[5]=2 0.000042 // e.g. utils/binstat.tick:424
/GOMAXPROCS=1,CPUS=8/what[internal-NumG]/size[9]=2 0.000012 // e.g. utils/binstat.tick:424
/GOMAXPROCS=1,CPUS=8/what[internal-NumG]/size[10-19]=9 0.000137 // e.g. utils/binstat.tick:424
/GOMAXPROCS=1,CPUS=8/what[internal-dump]/time[0.000600-0.000699]=1 0.000650 // e.g. utils/binstat.dump:436
/GOMAXPROCS=1,CPUS=8/what[loop-0]/time[1.000000-1.999999]=1 1.812913 // e.g. utils/binstat_test.TestWithPprof:176
  • This part is when GOMAXPROCS=8.
    • Note: The f1 - f6 functions executed in parallel without pre-emption & therefore quicker.
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f1]/time[0.070000-0.079999]=2 0.145029 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f1]/time[0.080000-0.089999]=1 0.082286 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f2]/time[0.070000-0.079999]=2 0.144383 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f2]/time[0.100000-0.199999]=1 0.100980 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f3]/time[0.070000-0.079999]=2 0.146867 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f3]/time[0.100000-0.199999]=1 0.106264 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f4]/time[0.070000-0.079999]=2 0.144903 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f4]/time[0.090000-0.099999]=1 0.098164 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f5]/time[0.070000-0.079999]=2 0.144949 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f5]/time[0.090000-0.099999]=1 0.098013 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f6]/time[0.070000-0.079999]=2 0.141520 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~1f-via-f6]/time[0.100000-0.199999]=1 0.103813 // e.g. utils/binstat_test.run.func1:83
/GOMAXPROCS=8,CPUS=8/what[~2egEnterTimeVal]/size[100-199]/time[0.000010-0.000019]=1 0.000017 // e.g. utils/binstat.TestBinstatInternal:20
/GOMAXPROCS=8,CPUS=8/what[~2egEnterTimeVal]/size[myPoint]/time[0.000005-0.000005]=1 0.000006 // e.g. utils/binstat.TestBinstatInternal:20
/GOMAXPROCS=8,CPUS=8/what[~2egEnter]/size[100-199]=1 0.000070 // e.g. utils/binstat.TestBinstatInternal:17
/GOMAXPROCS=8,CPUS=8/what[~2egenterTimeValInternal]/size[100-199]/time[0.000004-0.000004]=1 0.000005 // e.g. utils/binstat.TestBinstatInternal:24
/GOMAXPROCS=8,CPUS=8/what[~2egenterTimeValInternal]/size[myPoint]/time[0.000002-0.000002]=1 0.000002 // e.g. utils/binstat.TestBinstatInternal:24
/GOMAXPROCS=8,CPUS=8/what[internal-NumG]/size[4]=5 0.000160 // e.g. utils/binstat.tick:424
/GOMAXPROCS=8,CPUS=8/what[internal-NumG]/size[5]=1 0.000029 // e.g. utils/binstat.tick:424
/GOMAXPROCS=8,CPUS=8/what[internal-NumG]/size[10-19]=2 0.000046 // e.g. utils/binstat.tick:424
/GOMAXPROCS=8,CPUS=8/what[internal-dump]/time[0.000900-0.000999]=1 0.000943 // e.g. utils/binstat.dump:436
/GOMAXPROCS=8,CPUS=8/what[loop-1]/time[0.800000-0.899999]=1 0.819436 // e.g. utils/binstat_test.TestWithPprof:176
  • This part shows internal timings, as well as the Unix time, elapsed seconds since process start, & the number of GCs and the total seconds they took..
/internal/GCStats=9 0.001566
/internal/binstat.debug=36 0.001022
/internal/binstat.enter=70 0.001932
/internal/binstat.point=71 0.000882
/internal/binstat.x_2_y=111 0.000383
/internal/second=1624493407 2.665259
"}

Environment variables

  • If BINSTAT_ENABLE exists, binstat is enabled. Default: Disabled.
  • If BINSTAT_VERBOSE exists, binstat outputs debug info & e.g. function location. Default: Disabled.
  • If BINSTAT_DMP_NAME exists, use it. Default: <process name>.pid-<process pid>.binstat.txt.
  • If BINSTAT_DMP_PATH exists, output dump to <BINSTAT_DMP_PATH>/<BINSTAT_DMP_NAME>. Default: ..
  • If BINSTAT_CUT_PATH exists, cut function name path with this. Default: =github.com/onflow/flow-go/.
  • If BINSTAT_LEN_WHAT exists, truncate <what> to <len> from ~<what>=<len>, e.g. ~f=99;~2eg=0.

Todo

  • Monitor this tsc github issue in case we can accelerate timing further.
  • How to best compress & access the per second binstat file from outside the container?

Documentation

Overview

Package binstat implements file based code statistics in bins.

Generate bin based statistics on code by wrapping it with binstat functions. Every wallclock second, binstat will output bins to a text file if changed.

API: 

bs := binstat.Enter[Time][Val]("<What>"[,<Val>])
binstat.Leave[Val](bs, [<Val>])

Bin (single text line in output file depends on .Enter*()/.Leave*() combo) anatomy: 

/GOMAXPROCS=8,CPUS=8/what[~4whatExampleOne]/size[<num>-<num>]/time[<num>-<num>]=<num> <num>
                                                                                      ^^^^^ Total wallclock
                                                                                ^^^^^ Number of samples
                                                             ^^^^^^^^^^^^^^^^^^ If .EnterTime*() used
                                           ^^^^^^^^^^^^^^^^^^ If <Val> given in .Enter*Val() or .LeaveVal()
                    ^^^^^^^^^^^^^^^^^^^^^^^ <What> string from .Enter*()
                           ^^^^^ default <What> length to include in bin unless BINSTAT_LEN_WHAT
^^^^^^^^^^^^^^^^^^^^ normally does not change

Size and time ranges are optional and auto generated from a single value or time. E.g. time 0.012345 will be transformed to the range 0.010000 to 0.019999. E.g. value 234 will be transformed to the range 200 to 299. Note: Value can be optionally given with .Enter*Val() or .Leave*Val() as appropriate.

Using different API combinations then a varity of bin formats are possible: 

/GOMAXPROCS=8,CPUS=8/what[~7formata]=<num> <num>
/GOMAXPROCS=8,CPUS=8/what[~7formatb]/size[<num>-<num>]=<num> <num>
/GOMAXPROCS=8,CPUS=8/what[~7formatc]/time[<num>-<num>]=<num> <num>
/GOMAXPROCS=8,CPUS=8/what[~7formatd]/size[<num>-<num>]/time[<num>-<num>]=<num> <num>

In this way, code can be called millions of times, but relatively few bins generated & updated.

The number of bins used at run-time & output can be modified at process start via env vars. E.g. By default binstat is disabled and binstat function will just return, using little CPU. E.g. BINSTAT_LEN_WHAT=~what=0 means disable this particular <What> stat. E.g. BINSTAT_LEN_WHAT=~what=99 means create a longer <What> (therefore more bins) for this particular <What> stat.

Note: binstat also outputs bins for its internal function statistics.

Please see API examples below.

Please see README for examples of commenting and uncommenting.

Please see test for example of binstat versus pprof.

Index

Examples

Constants

View Source 
const (
	BinNet    = "~3net"
	BinStdmap = "~6stdmap"
	BinMakeID = "~6MakeID"
)

Variables

This section is empty.

Functions

func Debug 

func Debug(bs *BinStat, text string)
Example

.Debug() only used for debugging binstat 

package main

import (
	"fmt"

	"github.com/onflow/flow-go/utils/binstat"
)

func main() {
	bs := binstat.Enter("~7exampleDebug") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	binstat.Debug(bs, "hello world")      // only for binstat debbuging, and enabled if env var BINSTAT_VERBOSE set
	binstat.Leave(bs)                     // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here
	// 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"}
	// e.g. STDOUT: {"level":"debug","message":"2.918504 71372=pid 18143200=tid utils/binstat_test.ExampleBinStat_Debug:301() // debug hello world"}
	// 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"}
	fmt.Printf("debug via STDOUT only")
}

Output:

debug via STDOUT only

func Dump 

func Dump(dmpNonDefaultName string)

Dump binstat text file. Normally called automatically once per second if bins have changed. Consider calling explicity before exiting process. Called explicity in tests so as not to wait one second.

func Leave 

func Leave(bs *BinStat) time.Duration

func LeaveVal 

func LeaveVal(bs *BinStat, callerSize int64) time.Duration
Example 
package main

import (
	"fmt"
	"os/exec"

	"github.com/onflow/flow-go/utils/binstat"
)

func grepOutputFileAndSanatize(file string, what string) []byte {
	binstat.Dump(file)
	cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what)
	out, err := exec.Command("bash", "-c", cmd).CombinedOutput()
	if err != nil {
		panic(err)
	}
	return out
}

func main() {
	bs := binstat.Enter("~7exampleLeaveVal")                                                      // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	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
	fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-leave-val.txt", "exampleLeaveVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes
}

Output:

/GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleLeaveVal]/size[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleLeaveVal:<num>

func Point 

func Point(bs *BinStat, pointUnique string) time.Duration

Types

type BinStat 

type BinStat struct {
	// contains filtered or unexported fields
}

func DebugParams 

func DebugParams(bs *BinStat, callerParams string) *BinStat
Example

.DebugParams() only used for debugging binstat 

package main

import (
	"fmt"

	"github.com/onflow/flow-go/utils/binstat"
)

func main() {
	bs := binstat.Enter("~7exampleDebug") // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	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
	binstat.Debug(bs, "hello world")      // only for debbuging, and enabled if env var BINSTAT_VERBOSE set
	binstat.Leave(bs)                     // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here
	// 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"}
	// e.g. STDOUT: {"level":"debug","message":"2.758255 72784=pid 18162119=tid utils/binstat_test.ExampleBinStat_DebugParams:314(foo=1) // debug hello world"}
	// 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"}
	fmt.Printf("debug via STDOUT only")
}

Output:

debug via STDOUT only

func Enter 

func Enter(what string) *BinStat
Example 
package main

import (
	"fmt"
	"os/exec"

	"github.com/onflow/flow-go/utils/binstat"
)

func grepOutputFileAndSanatize(file string, what string) []byte {
	binstat.Dump(file)
	cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what)
	out, err := exec.Command("bash", "-c", cmd).CombinedOutput()
	if err != nil {
		panic(err)
	}
	return out
}

func main() {
	bs := binstat.Enter("~7exampleEnter")                                                  // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	binstat.Leave(bs)                                                                      // .Enter*()/.Leave*() creates bin and (a) increments its counter, (b) accumulates its time spent executing code here
	fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter.txt", "exampleEnter")) // force binstat output & grep & sanitize line; digits to <num> so example test passes
}

Output:

/GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnter]=<num> <num> // e.g. utils/binstat_test.ExampleEnter:<num>

func EnterTime 

func EnterTime(what string) *BinStat
Example 
package main

import (
	"fmt"
	"os/exec"

	"github.com/onflow/flow-go/utils/binstat"
)

func grepOutputFileAndSanatize(file string, what string) []byte {
	binstat.Dump(file)
	cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what)
	out, err := exec.Command("bash", "-c", cmd).CombinedOutput()
	if err != nil {
		panic(err)
	}
	return out
}

func main() {
	bs := binstat.EnterTime("~7exampleEnterTime")                                                   // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	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
	fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-time.txt", "exampleEnterTime")) // force binstat output & grep & sanitize line; digits to <num> so example test passes
}

Output:

/GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterTime]/time[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterTime:<num>

func EnterTimeVal 

func EnterTimeVal(what string, callerSize int64) *BinStat
Example 
package main

import (
	"fmt"
	"os/exec"

	"github.com/onflow/flow-go/utils/binstat"
)

func grepOutputFileAndSanatize(file string, what string) []byte {
	binstat.Dump(file)
	cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what)
	out, err := exec.Command("bash", "-c", cmd).CombinedOutput()
	if err != nil {
		panic(err)
	}
	return out
}

func main() {
	bs := binstat.EnterTimeVal("~7exampleEnterTimeVal", 123)                                               // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	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
	fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-time-val.txt", "exampleEnterTimeVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes
}

Output:

/GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterTimeVal]/size[<num>-<num>]/time[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterTimeVal:<num>

func EnterVal 

func EnterVal(what string, callerSize int64) *BinStat
Example 
package main

import (
	"fmt"
	"os/exec"

	"github.com/onflow/flow-go/utils/binstat"
)

func grepOutputFileAndSanatize(file string, what string) []byte {
	binstat.Dump(file)
	cmd := fmt.Sprintf("cat ./binstat.test.pid-*.binstat.txt%s | egrep '%s' | perl -lane 's~\\d[\\d\\.]*~<num>~g; print;'", file, what)
	out, err := exec.Command("bash", "-c", cmd).CombinedOutput()
	if err != nil {
		panic(err)
	}
	return out
}

func main() {
	bs := binstat.EnterVal("~7exampleEnterVal", 123)                                              // only 7 chars copied into bin unless env var set to e.g. BINSTAT_LEN_WHAT=~example=99")
	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
	fmt.Printf("%s", grepOutputFileAndSanatize(".test-example-enter-val.txt", "exampleEnterVal")) // force binstat output & grep & sanitize line; digits to <num> so example test passes
}

Output:

/GOMAXPROCS=<num>,CPUS=<num>/what[~<num>exampleEnterVal]/size[<num>-<num>]=<num> <num> // e.g. utils/binstat_test.ExampleEnterVal:<num>

func (*BinStat) GetSizeRange 

func (bs *BinStat) GetSizeRange() string

functions for exposing binstat internals e.g. for running non-production experiments sampling data, etc

func (*BinStat) GetTimeRange 

func (bs *BinStat) GetTimeRange() string

func (*BinStat) GetWhat 

func (bs *BinStat) GetWhat() string

Source Files

View all Source files

Jump to

Keyboard shortcuts

? : This menu
/ : Search site
f or F : Jump to
y or Y : Canonical URL
go.dev uses cookies from Google to deliver and enhance the quality of its services and to analyze traffic. Learn more.