From d58f4e9b7b503ed83641e2cd632a19011da6b50c Mon Sep 17 00:00:00 2001 From: "Hana (Hyang-Ah) Kim" Date: Mon, 24 Jul 2017 11:51:03 -0400 Subject: [PATCH] runtime/trace: fix corrupted trace during StartTrace Since Go1.8, different types of GC mark workers were annotated and the annotation strings were recorded during StartTrace. This change fixes two issues around the use of traceString from StartTrace here. 1) "failed to parse trace: no consistent ordering of events possible" This issue is a result of a missing 'batch' event entry. For efficient tracing, tracer maintains system allocated buffers and once a buffer is full, it is Flushed out for writing. Moreover, tracing assumes all the records in the same buffer (batch) are already ordered and implements more optimization in encoding and defers the completing order reconstruction till the trace parsing time. Thus, when a Flush happens and a new buffer is used, the new buffer should contain an event to indicate the start of a new batch. Before this CL, the batch entry was written only by traceEvent only when the buffer position is 0 and wasn't written when flush occurs during traceString. This CL fixes it by moving the batch entry write to the traceFlush. 2) crash during tracing due to invalid memory access, or during parsing due to duplicate string entries This issue is a result of memory allocation during traceString calls. Execution tracer traces some memory allocation activities. Before this CL, traceString took the buffer address (*traceBuf) and mutated the buffer. If memory tracing occurs in the meantime from the same P, the allocation tracing (traceEvent) will take the same buffer address through the pointer to the buffer address (**traceBuf), and mutate the buffer. As a result, one of the followings can happen: - the allocation record is overwritten by the following trace string record (data loss) - if buffer flush occurs during the allocation tracing, traceString will attempt to write the string record to the old buffer and eventually causes invalid memory access crash. - or flush on the same buffer can occur twice (once from the memory allocation, and once from the string record write), and in this case the trace can contain the same data twice and the parse will complain about duplicate string record entries. This CL fixes the second issue by making the traceString take **traceBuf (*traceBufPtr). Change-Id: I24f629758625b38e1916fbfc7d7be6ea210586af Reviewed-on: https://go-review.googlesource.com/50873 Run-TryBot: Austin Clements Run-TryBot: Hyang-Ah Hana Kim TryBot-Result: Gobot Gobot Reviewed-by: Austin Clements --- src/runtime/trace.go | 77 ++++++++++++++++++++------------- src/runtime/trace/trace_test.go | 57 ++++++++++++++++++++++++ 2 files changed, 103 insertions(+), 31 deletions(-) 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 { -- 2.48.1