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 ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^ ^