github.com/onflow/flow-go@v0.35.7-crescendo-preview.23-atree-inlining/utils/binstat/binstat.go (about)

     1  /*
     2  Package binstat implements file based code statistics in bins.
     3  
     4  Generate bin based statistics on code by wrapping it with binstat functions.
     5  Every wallclock second, binstat will output bins to a text file if changed.
     6  
     7  API:
     8  
     9  	bs := binstat.Enter[Time][Val]("<What>"[,<Val>])
    10  	binstat.Leave[Val](bs, [<Val>])
    11  
    12  Bin (single text line in output file depends on .Enter*()/.Leave*() combo) anatomy:
    13  
    14  	/GOMAXPROCS=8,CPUS=8/what[~4whatExampleOne]/size[<num>-<num>]/time[<num>-<num>]=<num> <num>
    15  	                                                                                      ^^^^^ Total wallclock
    16  	                                                                                ^^^^^ Number of samples
    17  	                                                             ^^^^^^^^^^^^^^^^^^ If .EnterTime*() used
    18  	                                           ^^^^^^^^^^^^^^^^^^ If <Val> given in .Enter*Val() or .LeaveVal()
    19  	                    ^^^^^^^^^^^^^^^^^^^^^^^ <What> string from .Enter*()
    20  	                           ^^^^^ default <What> length to include in bin unless BINSTAT_LEN_WHAT
    21  	^^^^^^^^^^^^^^^^^^^^ normally does not change
    22  
    23  Size and time ranges are optional and auto generated from a single value or time.
    24  E.g. time 0.012345 will be transformed to the range 0.010000 to 0.019999.
    25  E.g. value 234 will be transformed to the range 200 to 299.
    26  Note: Value can be optionally given with .Enter*Val() or .Leave*Val() as appropriate.
    27  
    28  Using different API combinations then a varity of bin formats are possible:
    29  
    30  	/GOMAXPROCS=8,CPUS=8/what[~7formata]=<num> <num>
    31  	/GOMAXPROCS=8,CPUS=8/what[~7formatb]/size[<num>-<num>]=<num> <num>
    32  	/GOMAXPROCS=8,CPUS=8/what[~7formatc]/time[<num>-<num>]=<num> <num>
    33  	/GOMAXPROCS=8,CPUS=8/what[~7formatd]/size[<num>-<num>]/time[<num>-<num>]=<num> <num>
    34  
    35  In this way, code can be called millions of times, but relatively few bins generated & updated.
    36  
    37  The number of bins used at run-time & output can be modified at process start via env vars.
    38  E.g. By default binstat is disabled and binstat function will just return, using little CPU.
    39  E.g. BINSTAT_LEN_WHAT=~what=0 means disable this particular <What> stat.
    40  E.g. BINSTAT_LEN_WHAT=~what=99 means create a longer <What> (therefore more bins) for this particular <What> stat.
    41  
    42  Note: binstat also outputs bins for its internal function statistics.
    43  
    44  Please see API examples below.
    45  
    46  Please see README for examples of commenting and uncommenting.
    47  
    48  Please see test for example of binstat versus pprof.
    49  */
    50  package binstat
    51  
    52  /*
    53  #if defined(__linux__)
    54  #include <stdint.h>
    55  #include <unistd.h>
    56  #include <sys/syscall.h>
    57  #ifdef SYS_gettid
    58  uint64_t gettid() { return syscall(SYS_gettid); }
    59  #else
    60  #error "SYS_gettid unavailable on this system"
    61  #endif
    62  #elif __APPLE__ // http://elliotth.blogspot.com/2012/04/gettid-on-mac-os.html
    63  #include <stdint.h>
    64  #include <pthread.h>
    65  uint64_t gettid() { uint64_t tid; pthread_threadid_np(NULL, &tid); return tid; }
    66  #elif defined(_WIN32)
    67  #include <stdint.h>
    68  #include <windows.h>
    69  uint64_t gettid() { return (uint64_t)GetCurrentThreadId(); }
    70  #else
    71  #   error "Unknown platform; __linux__ or __APPLE__ or _WIN32 expected"
    72  #endif
    73  */
    74  import "C"
    75  
    76  import (
    77  	"fmt"
    78  	"os"
    79  	"path/filepath"
    80  	"runtime"
    81  	"runtime/debug"
    82  	"strconv"
    83  	"strings"
    84  	"sync"
    85  	"sync/atomic"
    86  	"time"
    87  
    88  	"github.com/rs/zerolog"
    89  )
    90  
    91  // todo: consider using something faster than runtime.nano() e.g. [1]
    92  // But is [1] maybe not safe with multiple CPUs? [2]
    93  // "Another concern is that if a thread is migrated on a different
    94  //  processor between two measurements, the counter might skip too much
    95  //  or even 'go back'." [3]
    96  // [1] https://github.com/templexxx/tsc/issues/8
    97  // [2] https://stackoverflow.com/questions/3388134/rdtsc-accuracy-across-cpu-cores
    98  // [3] https://coherent-labs.com/posts/timestamps-for-performance-measurements/
    99  
   100  type globalStruct struct {
   101  	rwMutex          sync.RWMutex
   102  	log              zerolog.Logger
   103  	dumps            uint64
   104  	dmpName          string
   105  	dmpPath          string
   106  	cutPath          string
   107  	processBaseName  string
   108  	processPid       int
   109  	index            int
   110  	indexInternalMax int
   111  	key2index        map[string]int
   112  	keysArray        []string
   113  	keysEgLoc        []string
   114  	frequency        []uint64
   115  	frequencyShadow  []uint64
   116  	accumMono        []uint64
   117  	accumMonoShadow  []uint64
   118  	verbose          bool
   119  	enable           bool
   120  	second           uint64
   121  	startTime        time.Time
   122  	startTimeMono    time.Duration
   123  	lenWhat          string         // e.g. "~Code=99;~X=99"
   124  	what2len         map[string]int // e.g. Code -> 99, X -> 99
   125  }
   126  
   127  type BinStat struct {
   128  	what           string
   129  	enterTime      time.Duration
   130  	callerFunc     string
   131  	callerLine     int
   132  	callerParams   string
   133  	callerTime     bool
   134  	callerSize     int64
   135  	callerSizeWhen int
   136  	keySizeRange   string
   137  	keyTimeRange   string
   138  }
   139  
   140  const (
   141  	sizeAtEnter = iota
   142  	sizeNotUsed
   143  	sizeAtLeave
   144  )
   145  
   146  const (
   147  	internalSec = iota
   148  	internalEnter
   149  	internalPoint
   150  	internalx_2_y
   151  	internalDebug
   152  	internalGC
   153  )
   154  
   155  var global = globalStruct{}
   156  
   157  //go:linkname runtimeNano runtime.nanotime
   158  func runtimeNano() int64
   159  
   160  func runtimeNanoAsTimeDuration() time.Duration {
   161  	return time.Duration(runtimeNano())
   162  }
   163  
   164  func atoi(s string) int {
   165  	v, _ := strconv.Atoi(s)
   166  	return v
   167  }
   168  
   169  func init() {
   170  	t1 := runtimeNanoAsTimeDuration()
   171  
   172  	// inspired by https://github.com/onflow/flow-go/blob/master/utils/unittest/logging.go
   173  	zerolog.TimestampFunc = func() time.Time { return time.Now().UTC() }
   174  	global.log = zerolog.New(os.Stderr).Level(zerolog.DebugLevel).With().Timestamp().Logger()
   175  
   176  	global.dumps = 0
   177  	global.startTime = time.Now()
   178  	global.startTimeMono = runtimeNanoAsTimeDuration()
   179  	global.processBaseName = filepath.Base(os.Args[0])
   180  	global.processPid = os.Getpid()
   181  	_, global.verbose = os.LookupEnv("BINSTAT_VERBOSE")
   182  	_, global.enable = os.LookupEnv("BINSTAT_ENABLE")
   183  	global.dmpName, _ = os.LookupEnv("BINSTAT_DMP_NAME")
   184  	if global.dmpName == "" {
   185  		global.dmpName = fmt.Sprintf("%s.pid-%06d.binstat.txt", global.processBaseName, global.processPid)
   186  	}
   187  	global.dmpPath, _ = os.LookupEnv("BINSTAT_DMP_PATH")
   188  	if global.dmpPath == "" {
   189  		global.dmpPath = "."
   190  	}
   191  	global.cutPath, _ = os.LookupEnv("BINSTAT_CUT_PATH")
   192  	if global.cutPath == "" {
   193  		global.cutPath = "github.com/onflow/flow-go/"
   194  	}
   195  	global.what2len = make(map[string]int)
   196  	global.lenWhat, _ = os.LookupEnv("BINSTAT_LEN_WHAT")
   197  	if len(global.lenWhat) > 0 {
   198  		parts := strings.Split(global.lenWhat, ";")
   199  		for n, part := range parts { // e.g. "~Code=99"
   200  			subParts := strings.Split(part, "=")
   201  			const leftAndRightParts = 2
   202  			if (len(subParts) != leftAndRightParts) || (subParts[0][0:1] != "~") || (0 == len(subParts[0][1:])) {
   203  				panic(fmt.Sprintf("ERROR: BINSTAT: BINSTAT_LEN_WHAT=%s <-- cannot parse <-- format should be ~<what prefix>=<max len>[;...], e.g. ~Code=99;~X=99\n", global.lenWhat))
   204  			}
   205  			k := subParts[0][1:]
   206  			v := atoi(subParts[1])
   207  			global.what2len[k] = v
   208  			if global.verbose {
   209  				elapsedThisProc := time.Duration(runtimeNanoAsTimeDuration() - global.startTimeMono).Seconds()
   210  				global.log.Debug().Msgf("%f %d=pid %d=tid init() // parsing .lenWhat=%s; extracted #%d k=%s v=%d", elapsedThisProc, os.Getpid(), int64(C.gettid()), global.lenWhat, n, k, v)
   211  			}
   212  		}
   213  	}
   214  	global.key2index = make(map[string]int)
   215  
   216  	appendInternalKey := func(keyIotaIndex int, name string) {
   217  		if keyIotaIndex != len(global.keysArray) {
   218  			panic(fmt.Sprintf("ERROR: BINSTAT: INTERNAL: %s", name))
   219  		}
   220  		global.keysArray = append(global.keysArray, name)
   221  		global.keysEgLoc = append(global.keysEgLoc, "")
   222  		global.frequency = append(global.frequency, 0)
   223  		global.accumMono = append(global.accumMono, 0)
   224  		global.frequencyShadow = append(global.frequencyShadow, 0)
   225  		global.accumMonoShadow = append(global.accumMonoShadow, 0)
   226  	}
   227  	appendInternalKey(internalSec, "/internal/second")
   228  	appendInternalKey(internalEnter, "/internal/binstat.enter")
   229  	appendInternalKey(internalPoint, "/internal/binstat.point")
   230  	appendInternalKey(internalx_2_y, "/internal/binstat.x_2_y")
   231  	appendInternalKey(internalDebug, "/internal/binstat.debug")
   232  	appendInternalKey(internalGC, "/internal/GCStats")
   233  
   234  	global.index = len(global.keysArray)
   235  	global.indexInternalMax = len(global.keysArray)
   236  	go tick(100 * time.Millisecond) // every 0.1 seconds
   237  
   238  	if global.verbose {
   239  		elapsedThisProc := time.Duration(runtimeNanoAsTimeDuration() - global.startTimeMono).Seconds()
   240  		global.log.Debug().Msgf("%f %d=pid %d=tid init() // .enable=%t .verbose=%t .dmpPath=%s .dmpName=%s .cutPath=%s .lenWhat=%s",
   241  			elapsedThisProc, os.Getpid(), int64(C.gettid()), global.enable, global.verbose, global.dmpPath, global.dmpName, global.cutPath, global.lenWhat)
   242  	}
   243  
   244  	t2 := runtimeNanoAsTimeDuration()
   245  	if t2 < t1 {
   246  		panic(fmt.Sprintf("ERROR: BINSTAT: INTERNAL: t1=%d but t2=%d\n", t1, t2))
   247  	}
   248  }
   249  
   250  func enterGeneric(what string, callerTime bool, callerSize int64, callerSizeWhen int, verbose bool) *BinStat {
   251  	if !global.enable {
   252  		return &BinStat{} // so that chained functions can be called even if binstat globally disabled
   253  	}
   254  
   255  	t := runtimeNanoAsTimeDuration()
   256  
   257  	funcName := ""
   258  	fileLine := 0
   259  	if global.verbose {
   260  		// todo: is there a way to speed up runtime.Caller() and/or runtime.FuncForPC() somehow? cache pc value or something like that?
   261  		pc, _, lineNum, _ := runtime.Caller(2) // 2 assumes private binStat.newGeneric() called indirectly via public stub function; please see eof
   262  		fn := runtime.FuncForPC(pc)
   263  		funcName = fn.Name()
   264  		funcName = strings.ReplaceAll(funcName, global.cutPath, "")
   265  		fileLine = lineNum
   266  	}
   267  
   268  	whatLen := len(what) // e.g. what = "~3net:wire"
   269  	const tildaCharLen = 1
   270  	const lenCharLen = 1
   271  	const whatCharLenMin = 1
   272  	if (what[0:1] == "~") && (len(what) >= (tildaCharLen + lenCharLen + whatCharLenMin)) {
   273  		// come here if what is "~<default len><what>", meaning that BINSTAT_LEN_WHAT may override <default len>
   274  		//                                     ^^^^^^ 1+ chars; alphanumeric what name which may be longer than default len
   275  		//                        ^^^^^^^^^^^^^ 1 char; digit means default what len 1-9
   276  		//                       ^ 1 char; tilda means use next digit as default len unless override len exists in .what2len map
   277  		whatLenDefault := atoi(what[1:2])
   278  		whatLen = whatLenDefault + tildaCharLen + lenCharLen
   279  		if whatLenOverride, keyExists := global.what2len[what[tildaCharLen+lenCharLen:whatLen]]; keyExists {
   280  			whatLen = whatLenOverride + tildaCharLen + lenCharLen
   281  		}
   282  		if whatLen > len(what) {
   283  			whatLen = len(what)
   284  		}
   285  	}
   286  
   287  	callerParams := ""
   288  	bs := BinStat{what[0:whatLen], t, funcName, fileLine, callerParams, callerTime, callerSize, callerSizeWhen, "", ""}
   289  
   290  	t2 := runtimeNanoAsTimeDuration()
   291  
   292  	if verbose && global.verbose {
   293  		elapsedThisProc := time.Duration(t2 - global.startTimeMono).Seconds()
   294  		elapsedThisFunc := time.Duration(t2 - t).Seconds()
   295  		global.log.Debug().Msgf("%f %d=pid %d=tid %s:%d(%s) // enter in %f // what[%s] .NumCPU()=%d .GOMAXPROCS(0)=%d .NumGoroutine()=%d",
   296  			elapsedThisProc, os.Getpid(), int64(C.gettid()), bs.callerFunc, bs.callerLine, bs.callerParams, elapsedThisFunc, what, runtime.NumCPU(), runtime.GOMAXPROCS(0), runtime.NumGoroutine())
   297  	}
   298  
   299  	// for internal accounting, atomically increment counters in (never appended to) shadow array; saving additional lock
   300  	atomic.AddUint64(&global.frequencyShadow[internalEnter], 1)
   301  	atomic.AddUint64(&global.accumMonoShadow[internalEnter], uint64(t2-t))
   302  
   303  	return &bs
   304  }
   305  
   306  func pointGeneric(bs *BinStat, pointUnique string, callerSize int64, callerSizeWhen int, verbose bool) time.Duration {
   307  	// if binstat disabled, or <what> disabled; "~#" == "~<default len><what>"
   308  	if (!global.enable) || (2 == len(bs.what)) {
   309  		return time.Duration(0)
   310  	}
   311  
   312  	t := runtimeNanoAsTimeDuration()
   313  
   314  	elapsedNanoAsTimeDuration := t - bs.enterTime
   315  	if sizeAtLeave == callerSizeWhen {
   316  		bs.callerSizeWhen = callerSizeWhen
   317  		bs.callerSize = callerSize
   318  	}
   319  	var pointType string
   320  	switch pointUnique {
   321  	case "Leave":
   322  		pointType = "leave"
   323  		switch bs.callerSizeWhen {
   324  		case sizeAtEnter:
   325  			bs.keySizeRange = fmt.Sprintf("/size[%s]", x_2_y(float64(bs.callerSize), true))
   326  		case sizeNotUsed:
   327  			bs.keySizeRange = ""
   328  		case sizeAtLeave:
   329  			bs.keySizeRange = fmt.Sprintf("/size[%s]", x_2_y(float64(bs.callerSize), true))
   330  		}
   331  	case "":
   332  	default:
   333  		pointType = "point"
   334  		bs.keySizeRange = fmt.Sprintf("/size[%s]", pointUnique)
   335  	}
   336  	if bs.callerTime {
   337  		elapsedSeconds := elapsedNanoAsTimeDuration.Seconds()
   338  		bs.keyTimeRange = fmt.Sprintf("/time[%s]", x_2_y(elapsedSeconds, false))
   339  	}
   340  	key := fmt.Sprintf("/GOMAXPROCS=%d,CPUS=%d/what[%s]%s%s", runtime.GOMAXPROCS(0), runtime.NumCPU(), bs.what, bs.keySizeRange, bs.keyTimeRange)
   341  
   342  tryAgainRaceCondition:
   343  	var frequency uint64
   344  	var accumMono uint64
   345  	global.rwMutex.RLock() // lock for many readers v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v
   346  	index, keyExists := global.key2index[key]
   347  	if keyExists {
   348  		frequency = atomic.AddUint64(&global.frequency[index], 1)
   349  		accumMono = atomic.AddUint64(&global.accumMono[index], uint64(elapsedNanoAsTimeDuration))
   350  	}
   351  	global.rwMutex.RUnlock() // unlock for many readers ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^
   352  
   353  	if !keyExists {
   354  		// come here to create new hash table bucket
   355  		keyEgLoc := ""
   356  		if global.verbose {
   357  			keyEgLoc = fmt.Sprintf(" // e.g. %s:%d", bs.callerFunc, bs.callerLine)
   358  		}
   359  		global.rwMutex.Lock() // lock for single writer v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v
   360  		_, keyExists = global.key2index[key]
   361  		if keyExists { // come here if another func beat us to key creation
   362  			global.rwMutex.Unlock() // unlock for single writer ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~
   363  			goto tryAgainRaceCondition
   364  		}
   365  		// come here to create key and associated counter array element
   366  		index = global.index
   367  		global.key2index[key] = index // https://stackoverflow.com/questions/36167200/how-safe-are-golang-maps-for-concurrent-read-write-operations
   368  		global.keysArray = append(global.keysArray, key)
   369  		global.keysEgLoc = append(global.keysEgLoc, keyEgLoc)
   370  		global.frequency = append(global.frequency, 1)
   371  		global.accumMono = append(global.accumMono, uint64(elapsedNanoAsTimeDuration))
   372  		global.index++
   373  		global.rwMutex.Unlock() // unlock for single writer ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^
   374  		frequency = 1
   375  		accumMono = uint64(elapsedNanoAsTimeDuration)
   376  	}
   377  	tOld := uint64(0)
   378  	tNew := uint64(0)
   379  	if verbose { // come here if NOT internal instrumentation, e.g. not binstat.dmp() etc
   380  		tNew = uint64(time.Duration(t - global.startTimeMono).Seconds())
   381  		tOld = atomic.SwapUint64(&global.second, tNew)
   382  	}
   383  	t2 := runtimeNanoAsTimeDuration()
   384  	if verbose && global.verbose {
   385  		hint := ""
   386  		if tNew > tOld {
   387  			global.dumps++
   388  			hint = fmt.Sprintf("; dump #%d", global.dumps)
   389  		}
   390  		elapsedThisProc := time.Duration(t2 - global.startTimeMono).Seconds()
   391  		elapsedSinceNew := elapsedNanoAsTimeDuration.Seconds()
   392  		global.log.Debug().Msgf("%f %d=pid %d=tid %s:%d(%s) // %s in %f // %s=[%d]=%d %f%s",
   393  			elapsedThisProc, os.Getpid(), int64(C.gettid()), bs.callerFunc, bs.callerLine, bs.callerParams, pointType, elapsedSinceNew, key, index, frequency, time.Duration(accumMono).Seconds(), hint)
   394  	}
   395  
   396  	// for internal accounting, atomically increment counters in (never appended to) shadow array; saving additional lock
   397  	atomic.AddUint64(&global.frequencyShadow[internalPoint], 1)
   398  	atomic.AddUint64(&global.accumMonoShadow[internalPoint], uint64(t2-t))
   399  
   400  	if tNew > tOld {
   401  		// come here if won lottery to save binStats this second
   402  		const UseDefaultName = ""
   403  		Dump(UseDefaultName)
   404  	}
   405  
   406  	return elapsedNanoAsTimeDuration
   407  }
   408  
   409  // todo: there must be a better / faster way to do all the operations below :-)
   410  // todo: allow configuration for more granular ranges, e.g. 1.100000-1.199999, or bigger ranges e.g. 0.200000-0.399999 ?
   411  // todo: consider outputting int range in hex for 16 bins instead of 10 bins (at a particular magnitude)?
   412  func x_2_y(v float64, isInt bool) string { // e.g. 12.345678
   413  	t := runtimeNanoAsTimeDuration()
   414  
   415  	var s string
   416  	if isInt {
   417  		s = fmt.Sprintf("%d", int64(v)) // e.g. "12"
   418  	} else {
   419  		s = fmt.Sprintf("%f", v) // e.g. "12.2345678"
   420  	}
   421  	// make lo & hi copy of strings
   422  	lo := []byte(s)
   423  	hi := []byte(s)
   424  	// find first non-zero digit
   425  	var z int
   426  	for z = 0; z < len(lo); z++ {
   427  		if (lo[z] != '0') && (lo[z] != '.') {
   428  			goto foundFirstNonZeroNonDot
   429  		}
   430  	}
   431  foundFirstNonZeroNonDot:
   432  	// turn the remaining lo digits to '0' and hi digits to '1'
   433  	z++
   434  	for i := z; i < len(lo); i++ {
   435  		if lo[i] != '.' {
   436  			lo[i] = '0'
   437  			hi[i] = '9'
   438  		}
   439  	}
   440  	returnString := fmt.Sprintf("%s-%s", lo, hi)
   441  
   442  	t2 := runtimeNanoAsTimeDuration()
   443  
   444  	// for internal accounting, atomically increment counters in (never appended to) shadow array; saving additional lock
   445  	atomic.AddUint64(&global.frequencyShadow[internalx_2_y], 1)
   446  	atomic.AddUint64(&global.accumMonoShadow[internalx_2_y], uint64(t2-t))
   447  
   448  	return returnString
   449  }
   450  
   451  func debugGeneric(bs *BinStat, debugText string, verbose bool) {
   452  	if !global.enable {
   453  		return
   454  	}
   455  
   456  	t := runtimeNanoAsTimeDuration()
   457  
   458  	if verbose && global.verbose {
   459  		elapsedThisProc := time.Duration(t - global.startTimeMono).Seconds()
   460  		global.log.Debug().Msgf("%f %d=pid %d=tid %s:%d(%s) // debug %s", elapsedThisProc, os.Getpid(), int64(C.gettid()), bs.callerFunc, bs.callerLine, bs.callerParams, debugText)
   461  	}
   462  
   463  	t2 := runtimeNanoAsTimeDuration()
   464  
   465  	// for internal accounting, atomically increment counters in (never appended to) shadow array; saving additional lock
   466  	atomic.AddUint64(&global.frequencyShadow[internalDebug], 1)
   467  	atomic.AddUint64(&global.accumMonoShadow[internalDebug], uint64(t2-t))
   468  }
   469  
   470  func tick(t time.Duration) {
   471  	if !global.enable {
   472  		return
   473  	}
   474  
   475  	ticker := time.NewTicker(t)
   476  	for range ticker.C {
   477  		bs := enter("internal-NumG")
   478  		leaveVal(bs, int64(runtime.NumGoroutine()))
   479  	}
   480  }
   481  
   482  func fatalPanic(err string) {
   483  	global.log.Fatal().Msg(err)
   484  	panic(err)
   485  }
   486  
   487  // todo: would a different format, like CSV or JSON, be useful and how would it be used?
   488  // todo: consider env var for path to bin dump file (instead of just current folder)?
   489  // todo: if bin dump file path is /dev/shm, add paranoid checking around filling up /dev/shm?
   490  // todo: consider reporting on num active go-routines [1] and/or SchedStats API [2] if/when available.
   491  // [1] https://github.com/golang/go/issues/17089 "runtime: expose number of running/runnable goroutines #17089"
   492  // [2] https://github.com/golang/go/issues/15490 "proposal: runtime: add SchedStats API #15490"
   493  
   494  // Dump binstat text file.
   495  // Normally called automatically once per second if bins have changed.
   496  // Consider calling explicity before exiting process.
   497  // Called explicity in tests so as not to wait one second.
   498  func Dump(dmpNonDefaultName string) {
   499  	bs := enterTime("internal-dump")
   500  	defer leave(bs)
   501  
   502  	var gcStats debug.GCStats
   503  	debug.ReadGCStats(&gcStats)
   504  	global.frequencyShadow[internalGC] = uint64(gcStats.NumGC)
   505  	global.accumMonoShadow[internalGC] = uint64(gcStats.PauseTotal)
   506  
   507  	global.rwMutex.RLock() // lock for many readers until function return
   508  	defer global.rwMutex.RUnlock()
   509  
   510  	// todo: copy into buffer and then write to file outside of reader lock?
   511  
   512  	t := time.Now()
   513  	seconds := uint64(t.Unix())
   514  	global.frequencyShadow[internalSec] = seconds
   515  	global.accumMonoShadow[internalSec] = uint64(runtimeNanoAsTimeDuration() - global.startTimeMono)
   516  
   517  	// copy internal accounting from never-appending shadow to appending non-shadow counters
   518  	for i := 0; i < global.indexInternalMax; i++ {
   519  		v1 := atomic.LoadUint64(&global.frequencyShadow[i])
   520  		atomic.StoreUint64(&global.frequency[i], v1)
   521  		v2 := atomic.LoadUint64(&global.accumMonoShadow[i])
   522  		atomic.StoreUint64(&global.accumMono[i], v2)
   523  	}
   524  
   525  	fileTmp := fmt.Sprintf("%s/%s.%d.tmp%s", global.dmpPath, global.dmpName, seconds, dmpNonDefaultName)
   526  	fileNew := fmt.Sprintf("%s/%s%s", global.dmpPath, global.dmpName, dmpNonDefaultName)
   527  	f, err := os.Create(fileTmp)
   528  	if err != nil {
   529  		fatalPanic(fmt.Sprintf("ERROR: BINSTAT: .Create(%s)=%s", fileTmp, err))
   530  	}
   531  	for i := range global.keysArray {
   532  		// grab these atomically (because they may be atomically updated in parallel) so as not to trigger Golang's "WARNING: DATA RACE"
   533  		u1 := atomic.LoadUint64(&global.frequency[i])
   534  		u2 := atomic.LoadUint64(&global.accumMono[i])
   535  		_, err := fmt.Fprintf(f, "%s=%d %f%s\n", global.keysArray[i], u1, time.Duration(u2).Seconds(), global.keysEgLoc[i])
   536  		if err != nil {
   537  			fatalPanic(fmt.Sprintf("ERROR: BINSTAT: .Fprintf()=%s", err))
   538  		}
   539  	}
   540  	err = f.Close()
   541  	if err != nil {
   542  		fatalPanic(fmt.Sprintf("ERROR: BINSTAT: .Close()=%s", err))
   543  	}
   544  	err = os.Rename(fileTmp, fileNew) // atomically rename / move on Linux :-)
   545  	if err != nil {
   546  		// sometimes -- very infrequently -- we come here with the error: "no such file or directory"
   547  		// in theory only one go-routine should write this uniquely named per second file, so how can the file 'disappear' for renaming?
   548  		// therefore this error results in a warning and not an error / panic, and the next second we just write the file again hopefuly :-)
   549  		global.log.Warn().Msgf("WARN: .Rename(%s, %s)=%s\n", fileTmp, fileNew, err)
   550  	}
   551  }
   552  
   553  // functions for exposing binstat internals e.g. for running non-production experiments sampling data, etc
   554  func (bs *BinStat) GetSizeRange() string { return bs.keySizeRange }
   555  func (bs *BinStat) GetTimeRange() string { return bs.keyTimeRange }
   556  func (bs *BinStat) GetWhat() string      { return bs.what }
   557  
   558  // functions BEFORE go fmt v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v v
   559  
   560  /*
   561  func Enter       (what string,                    ) *BinStat      { return enterGeneric(what, false       , 0         , sizeNotUsed, true ) }
   562  func enter       (what string                     ) *BinStat      { return enterGeneric(what, false       , 0         , sizeNotUsed, false) }
   563  func EnterVal    (what string, callerSize   int64 ) *BinStat      { return enterGeneric(what, false       , callerSize, sizeAtEnter, true ) }
   564  func enterVal    (what string, callerSize   int64 ) *BinStat      { return enterGeneric(what, false       , callerSize, sizeAtEnter, false) }
   565  func EnterTime   (what string,                    ) *BinStat      { return enterGeneric(what, true        , 0         , sizeNotUsed, true ) }
   566  func enterTime   (what string                     ) *BinStat      { return enterGeneric(what, true        , 0         , sizeNotUsed, false) }
   567  func EnterTimeVal(what string, callerSize   int64 ) *BinStat      { return enterGeneric(what, true        , callerSize, sizeAtEnter, true ) }
   568  func enterTimeVal(what string, callerSize   int64 ) *BinStat      { return enterGeneric(what, true        , callerSize, sizeAtEnter, false) }
   569  
   570  func DebugParams (bs *BinStat, callerParams string) *BinStat      {        bs.callerParams  = callerParams; return bs                       }
   571  func Debug       (bs *BinStat, text         string)               {        debugGeneric(bs  , text                                 , true ) }
   572  
   573  func Point       (bs *BinStat, pointUnique  string) time.Duration { return pointGeneric(bs  , pointUnique , 0         , sizeNotUsed, true ) }
   574  func point       (bs *BinStat, pointUnique  string) time.Duration { return pointGeneric(bs  , pointUnique , 0         , sizeNotUsed, false) }
   575  func Leave       (bs *BinStat                     ) time.Duration { return pointGeneric(bs  , "Leave"     , 0         , sizeNotUsed, true ) }
   576  func leave       (bs *BinStat                     ) time.Duration { return pointGeneric(bs  , "Leave"     , 0         , sizeNotUsed, false) }
   577  func LeaveVal    (bs *BinStat, callerSize   int64 ) time.Duration { return pointGeneric(bs  , "Leave"     , callerSize, sizeAtLeave, true ) }
   578  func leaveVal    (bs *BinStat, callerSize   int64 ) time.Duration { return pointGeneric(bs  , "Leave"     , callerSize, sizeAtLeave, false) }
   579  */
   580  
   581  // functions W/&W/O go fmt ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~ ~
   582  
   583  func Enter(what string) *BinStat { return enterGeneric(what, false, 0, sizeNotUsed, true) }
   584  func enter(what string) *BinStat { return enterGeneric(what, false, 0, sizeNotUsed, false) }
   585  func EnterVal(what string, callerSize int64) *BinStat {
   586  	return enterGeneric(what, false, callerSize, sizeAtEnter, true)
   587  }
   588  func enterVal(what string, callerSize int64) *BinStat {
   589  	return enterGeneric(what, false, callerSize, sizeAtEnter, false)
   590  }
   591  func EnterTime(what string) *BinStat { return enterGeneric(what, true, 0, sizeNotUsed, true) }
   592  func enterTime(what string) *BinStat { return enterGeneric(what, true, 0, sizeNotUsed, false) }
   593  func EnterTimeVal(what string, callerSize int64) *BinStat {
   594  	return enterGeneric(what, true, callerSize, sizeAtEnter, true)
   595  }
   596  func enterTimeVal(what string, callerSize int64) *BinStat {
   597  	return enterGeneric(what, true, callerSize, sizeAtEnter, false)
   598  }
   599  
   600  func DebugParams(bs *BinStat, callerParams string) *BinStat {
   601  	bs.callerParams = callerParams
   602  	return bs
   603  }
   604  func Debug(bs *BinStat, text string) { debugGeneric(bs, text, true) }
   605  
   606  func Point(bs *BinStat, pointUnique string) time.Duration {
   607  	return pointGeneric(bs, pointUnique, 0, sizeNotUsed, true)
   608  }
   609  func point(bs *BinStat, pointUnique string) time.Duration {
   610  	return pointGeneric(bs, pointUnique, 0, sizeNotUsed, false)
   611  }
   612  func Leave(bs *BinStat) time.Duration { return pointGeneric(bs, "Leave", 0, sizeNotUsed, true) }
   613  func leave(bs *BinStat) time.Duration { return pointGeneric(bs, "Leave", 0, sizeNotUsed, false) }
   614  func LeaveVal(bs *BinStat, callerSize int64) time.Duration {
   615  	return pointGeneric(bs, "Leave", callerSize, sizeAtLeave, true)
   616  }
   617  func leaveVal(bs *BinStat, callerSize int64) time.Duration {
   618  	return pointGeneric(bs, "Leave", callerSize, sizeAtLeave, false)
   619  }
   620  
   621  // functions AFTER  go fmt ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^