diff --git a/src/runtime/trace.go b/src/runtime/trace.go index e179e18b9f..fab797601b 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -235,21 +235,21 @@ func StartTrace() error { trace.timeStart = nanotime() trace.headerWritten = false trace.footerWritten = false - trace.strings = make(map[string]uint64) + + // string to id mapping + // 0 : reserved for an empty string + // remaining: other strings registered by traceString trace.stringSeq = 0 + trace.strings = make(map[string]uint64) + trace.seqGC = 0 _g_.m.startingtrace = false trace.enabled = true // Register runtime goroutine labels. _, pid, bufp := traceAcquireBuffer() - buf := (*bufp).ptr() - if buf == nil { - buf = traceFlush(0).ptr() - (*bufp).set(buf) - } for i, label := range gcMarkWorkerModeStrings[:] { - trace.markWorkerLabels[i], buf = traceString(buf, label) + trace.markWorkerLabels[i], bufp = traceString(bufp, pid, label) } traceReleaseBuffer(pid) @@ -513,18 +513,12 @@ func traceEvent(ev byte, skip int, args ...uint64) { buf := (*bufp).ptr() const maxSize = 2 + 5*traceBytesPerNumber // event type, length, sequence, timestamp, stack id and two add params if buf == nil || len(buf.arr)-buf.pos < maxSize { - buf = traceFlush(traceBufPtrOf(buf)).ptr() + buf = traceFlush(traceBufPtrOf(buf), pid).ptr() (*bufp).set(buf) } ticks := uint64(cputicks()) / traceTickDiv tickDiff := ticks - buf.lastTicks - if buf.pos == 0 { - buf.byte(traceEvBatch | 1<= 0 { @@ -602,7 +596,7 @@ func traceReleaseBuffer(pid int32) { } // traceFlush puts buf onto stack of full buffers and returns an empty buffer. -func traceFlush(buf traceBufPtr) traceBufPtr { +func traceFlush(buf traceBufPtr, pid int32) traceBufPtr { owner := trace.lockOwner dolock := owner == nil || owner != getg().m.curg if dolock { @@ -623,34 +617,51 @@ func traceFlush(buf traceBufPtr) traceBufPtr { bufp := buf.ptr() bufp.link.set(nil) bufp.pos = 0 - bufp.lastTicks = 0 + + // initialize the buffer for a new batch + ticks := uint64(cputicks()) / traceTickDiv + bufp.lastTicks = ticks + bufp.byte(traceEvBatch | 1< maxLen { fn = fn[len(fn)-maxLen:] } - frame.funcID, buf = traceString(buf, fn) + frame.funcID, bufp = traceString(bufp, pid, fn) frame.line = uint64(f.Line) file := f.File if len(file) > maxLen { file = file[len(file)-maxLen:] } - frame.fileID, buf = traceString(buf, file) - return frame, buf + frame.fileID, bufp = traceString(bufp, pid, file) + return frame, (*bufp) } // traceAlloc is a non-thread-safe region allocator. diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go index c5f64fcf4c..5fa5b82f8e 100644 --- a/src/runtime/trace/trace_test.go +++ b/src/runtime/trace/trace_test.go @@ -7,6 +7,7 @@ package trace_test import ( "bytes" "flag" + "internal/race" "internal/trace" "io" "io/ioutil" @@ -14,6 +15,7 @@ import ( "os" "runtime" . "runtime/trace" + "strconv" "sync" "testing" "time" @@ -23,6 +25,61 @@ var ( saveTraces = flag.Bool("savetraces", false, "save traces collected by tests") ) +// TestEventBatch tests Flush calls that happen during Start +// don't produce corrupted traces. +func TestEventBatch(t *testing.T) { + if race.Enabled { + t.Skip("skipping in race mode") + } + if testing.Short() { + t.Skip("skipping in short mode") + } + // During Start, bunch of records are written to reflect the current + // snapshot of the program, including state of each goroutines. + // And some string constants are written to the trace to aid trace + // parsing. This test checks Flush of the buffer occurred during + // this process doesn't cause corrupted traces. + // When a Flush is called during Start is complicated + // so we test with a range of number of goroutines hoping that one + // of them triggers Flush. + // This range was chosen to fill up a ~64KB buffer with traceEvGoCreate + // and traceEvGoWaiting events (12~13bytes per goroutine). + for g := 4950; g < 5050; g++ { + n := g + t.Run("G="+strconv.Itoa(n), func(t *testing.T) { + var wg sync.WaitGroup + wg.Add(n) + + in := make(chan bool, 1000) + for i := 0; i < n; i++ { + go func() { + <-in + wg.Done() + }() + } + buf := new(bytes.Buffer) + if err := Start(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + + for i := 0; i < n; i++ { + in <- true + } + wg.Wait() + Stop() + + _, err := trace.Parse(buf, "") + if err == trace.ErrTimeOrder { + t.Skipf("skipping trace: %v", err) + } + + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + }) + } +} + func TestTraceStartStop(t *testing.T) { buf := new(bytes.Buffer) if err := Start(buf); err != nil {