Commit cc6a7fce authored by Austin Clements's avatar Austin Clements

runtime: increase precision of gctrace times

Currently we truncate gctrace clock and CPU times to millisecond
precision. As a result, many phases are typically printed as 0, which
is fine for user consumption, but makes gathering statistics and
reports over GC traces difficult.

In 1.4, the gctrace line printed times in microseconds. This was
better for statistics, but not as easy for users to read or interpret,
and it generally made the trace lines longer.

This change strikes a balance between these extremes by printing
milliseconds, but including the decimal part to two significant
figures down to microsecond precision. This remains easy to read and
interpret, but includes more precision when it's useful.

For example, where the code currently prints,

gc #29 @1.629s 0%: 0+2+0+12+0 ms clock, 0+2+0+0/12/0+0 ms cpu, 4->4->2 MB, 4 MB goal, 1 P

this prints,

gc #29 @1.629s 0%: 0.005+2.1+0+12+0.29 ms clock, 0.005+2.1+0+0/12/0+0.29 ms cpu, 4->4->2 MB, 4 MB goal, 1 P

Fixes #10970.

Change-Id: I249624779433927cd8b0947b986df9060c289075
Reviewed-on: https://go-review.googlesource.com/10554Reviewed-by: 's avatarRuss Cox <rsc@golang.org>
parent 32166319
...@@ -994,19 +994,26 @@ func gc(mode int) { ...@@ -994,19 +994,26 @@ func gc(mode int) {
printlock() printlock()
print("gc #", memstats.numgc, print("gc #", memstats.numgc,
" @", string(itoaDiv(sbuf[:], uint64(tEnd-runtimeInitTime)/1e6, 3)), "s ", " @", string(itoaDiv(sbuf[:], uint64(tEnd-runtimeInitTime)/1e6, 3)), "s ",
util, "%: ", util, "%: ")
(tScan-tSweepTerm)/1e6, prev := tSweepTerm
"+", (tInstallWB-tScan)/1e6, for i, ns := range []int64{tScan, tInstallWB, tMark, tMarkTerm, tEnd} {
"+", (tMark-tInstallWB)/1e6, if i != 0 {
"+", (tMarkTerm-tMark)/1e6, print("+")
"+", (tEnd-tMarkTerm)/1e6, " ms clock, ", }
sweepTermCpu/1e6, print(string(fmtNSAsMS(sbuf[:], uint64(ns-prev))))
"+", scanCpu/1e6, prev = ns
"+", installWBCpu/1e6, }
"+", gcController.assistTime/1e6, print(" ms clock, ")
"/", (gcController.dedicatedMarkTime+gcController.fractionalMarkTime)/1e6, for i, ns := range []int64{sweepTermCpu, scanCpu, installWBCpu, gcController.assistTime, gcController.dedicatedMarkTime + gcController.fractionalMarkTime, gcController.idleMarkTime, markTermCpu} {
"/", gcController.idleMarkTime/1e6, if i == 4 || i == 5 {
"+", markTermCpu/1e6, " ms cpu, ", // Separate mark time components with /.
print("/")
} else if i != 0 {
print("+")
}
print(string(fmtNSAsMS(sbuf[:], uint64(ns))))
}
print(" ms cpu, ",
heap0>>20, "->", heap1>>20, "->", heap2>>20, " MB, ", heap0>>20, "->", heap1>>20, "->", heap2>>20, " MB, ",
heapGoal>>20, " MB goal, ", heapGoal>>20, " MB goal, ",
maxprocs, " P") maxprocs, " P")
...@@ -1514,3 +1521,23 @@ func itoaDiv(buf []byte, val uint64, dec int) []byte { ...@@ -1514,3 +1521,23 @@ func itoaDiv(buf []byte, val uint64, dec int) []byte {
buf[i] = byte(val + '0') buf[i] = byte(val + '0')
return buf[i:] return buf[i:]
} }
// fmtNSAsMS nicely formats ns nanoseconds as milliseconds.
func fmtNSAsMS(buf []byte, ns uint64) []byte {
if ns >= 10e6 {
// Format as whole milliseconds.
return itoaDiv(buf, ns/1e6, 0)
}
// Format two digits of precision, with at most three decimal places.
x := ns / 1e3
if x == 0 {
buf[0] = '0'
return buf[:1]
}
dec := 3
for x >= 100 {
x /= 10
dec--
}
return itoaDiv(buf, x, dec)
}
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment