binstat

package

v0.30.3-fix-event-stre... Latest Latest Go to latest Published: Apr 17, 2023 License: AGPL-3.0 Imports: 12 Imported by: 0

Details

Valid go.mod file
Redistributable license
Tagged version
Stable version
Learn more about best practices

Repository

github.com/onflow/flow-go

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 ¶

Constants
func Debug(bs *BinStat, text string)
func Dump(dmpNonDefaultName string)
func Leave(bs *BinStat) time.Duration
func LeaveVal(bs *BinStat, callerSize int64) time.Duration
func Point(bs *BinStat, pointUnique string) time.Duration
type BinStat

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

?	: This menu
/	: Search site
f or F	: Jump to
y or Y	: Canonical URL

README ¶

binstat - run-time & space efficient stats in bins

Why use binstat?

binstat goals

How binstat works?

How 'collapsable' <what> works?

Disable AKA 'hide' binstat instrumentation before pushing code

What makes binstat efficient?

Example comparison with pprof

Environment variables

Todo

Documentation ¶

Overview ¶

Index ¶

Examples ¶

Constants ¶

Variables ¶

Functions ¶

func Debug ¶

func Dump ¶

func Leave ¶

func LeaveVal ¶

func Point ¶

Types ¶

type BinStat ¶

func DebugParams ¶

func Enter ¶

func EnterTime ¶

func EnterTimeVal ¶

func EnterVal ¶

func (*BinStat) GetSizeRange ¶

func (*BinStat) GetTimeRange ¶

func (*BinStat) GetWhat ¶

Source Files ¶

`binstat` - run-time & space efficient stats in bins

Why use `binstat`?

`binstat` goals

How `binstat` works?

How 'collapsable' `<what>` works?

Disable AKA 'hide' `binstat` instrumentation before pushing code

What makes `binstat` efficient?

Example comparison with `pprof`