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