Tracing

The previous lesson stopped at counting how many values a program allocates — only a program’s memory dimension. But a program’s runtime contains more than this: which goroutine started when, how many ran concurrently. This lesson looks at this broader record: the language’s own execution trace records the events that happen during a program’s run, and this lesson reads that record as an event count.

All four lessons of this topic proceeded the same way: first classify where a fact comes from (source, tool, run), then measure the limit specific to that class. Profile and the escape decision were two separate classes — one a run, one a tool. Allocation count was a run fact again, but it looked at four comparisons rather than a single number. This last lesson returns to a run, but what it asks is a kind never asked before: how many separate units of execution actually ran.

The execution trace is also an example of the distinction that has held since this course’s first lesson — a run fact: someone looking at the source cannot see how many goroutines actually ran, they can only run it and ask. But the number read in this lesson captures something different from a profile or an allocation count: not memory, but concurrency itself. This course’s four measurement axes (M09/K03) are not used here; this lesson only compares the event counts the two setups produce.

The word “tracing” is used here in a narrow sense: the language’s own execution trace mechanism, not a profile or a log. A profile asked “how many values were allocated”; a log (another mechanism not separately covered in this course) holds the messages the application itself writes. An execution trace differs from both: it is a mechanism through which the runtime itself records which execution unit it ran at which moments. This lesson measures only the part of that mechanism that uses application-specific markers.

Why A Tagged Count, Not A Raw Number

An execution trace does not only record the work the program writes; it also records the runtime’s own background work — how the scheduler distributes a thread, when the garbage collector starts a scan. This background activity depends on the machine’s load at that moment and the operating system’s scheduling, and it changes from run to run. This is why a trace’s total event count — if background activity is counted along with everything the program itself writes — can come out different across two separate runs, even with the same source code.

This lesson does not measure this variability, it avoids it: instead of the total count, it counts how many times two tags it chose itself (record-process, worker-start) appear. These tags appear only in this program’s own code and never show up in background activity — this is why, unlike the total event count, these two numbers stay constant from run to run. The course’s stability pattern applies here too: a measured number does not enter the table before it is proven deterministic first.

This choice is a direct continuation of the search for reproducibility in the previous three lessons: the profile number was counted usable because it gave a single value across five runs, and the allocation count passed the same test. The execution trace cannot pass this test on its own — in its raw form it changes from run to run — but one part of the trace, the part it tags itself, does. This lesson therefore measures not the whole trace, but the part of it that comes out stable.

Reading The Trace With Tags

An execution trace’s raw content carries everything forbidden to print in this course: goroutine numbers, timestamps, stack traces. This lesson never prints this content; instead, it searches the trace for the two tags it chose itself and counts only how many times these tags appear.

// trace.go — creates the trace file and counts how many times a tag appears in it
package main

import (
	"context"
	"os"
	"os/exec"
	"runtime/trace"
	"strings"
)

const recordTag = "record-process"
const workerStartTag = "worker-start"

// recordTrace records the given work into a trace file and returns its path;
// the path is never printed, it is only used inside this function.
func recordTrace(f func(ctx context.Context)) string {
	dir, _ := os.MkdirTemp("", "trace")
	path := dir + "/trace.out"
	file, _ := os.Create(path)
	trace.Start(file)
	f(context.Background())
	trace.Stop()
	file.Close()
	return path
}

// eventCount hands the trace file to the trace tool and counts only how many
// times the requested tag appears. The tool's output text is never printed.
func eventCount(tracePath, tag string) int {
	cmd := exec.Command("go", "tool", "trace", "-d=parsed", tracePath)
	cmd.Env = append(os.Environ(), "GOTOOLCHAIN=local")
	output, _ := cmd.CombinedOutput()
	return strings.Count(string(output), tag)
}

PM7. eventCount reads the text the trace tool produces but never writes it to the screen — it only counts how many times a substring appears with strings.Count and returns that count. The trace tool’s own output carries goroutine numbers, timestamps, and full file paths; none of these is even assigned to a variable anywhere in the program, they are consumed and discarded directly inside the counting operation.

recordTrace carries a similar discipline: the trace file’s path sits in a temporary directory set up with os.MkdirTemp, and this path is only used to be passed to eventCount — it never enters any fmt.Println call. The function signature is deliberate too: by taking f func(ctx context.Context), it leaves the work to be traced to the caller. This is why the same recordTrace function can be used to trace both the sequential and the pooled setup — only which function is called changes, the tracing mechanics stay the same.

Why Three Workers

The pooled setup opens three workers and processes six records — the worker count deliberately does not divide the record count evenly: each worker is forced to process two records on average, but the order of reading from the channel is not known in advance, so which worker gets how many records can vary from run to run. This lesson never measures that distribution — it only counts that three workers started, not how many records each of them got. This is a deliberate limit so as not to mix with an axis the course established in M09/K03 and does not use here (how a goroutine stops): this lesson measures only how many execution units exist, not the sharing among them.

Two Setups: Sequential And Pooled

The measurement below processes the same six records two separate ways. The sequential setup processes every record in the calling goroutine itself, in order. The pooled setup distributes the same six records across three worker goroutines; each worker drops a tagged record once when it starts, then processes records coming from the channel. In both setups, every record is marked with the same tag through trace.WithRegion.

// measurement.go — same work, two setups: sequential and a pool of three workers
package main

import (
	"context"
	"fmt"
	"os"
	"runtime/trace"
	"strconv"
	"sync"
)

type Record struct {
	Name   string
	Amount int
}

var records = []Record{
	{"bolt", 1}, {"nut", 2}, {"washer", 3}, {"nail", 4}, {"bolt", 5}, {"spacer", 6},
}

func process(ctx context.Context, k Record) int {
	result := 0
	trace.WithRegion(ctx, recordTag, func() {
		result = k.Amount * 2
	})
	return result
}

func sequential(ctx context.Context) int {
	total := 0
	for _, k := range records {
		total += process(ctx, k)
	}
	return total
}

func pooled(ctx context.Context, workerCount int) int {
	work := make(chan Record)
	var mu sync.Mutex
	total := 0
	var wg sync.WaitGroup
	for id := 0; id < workerCount; id++ {
		wg.Add(1)
		go func(id int) {
			defer wg.Done()
			trace.Log(ctx, workerStartTag, strconv.Itoa(id))
			for k := range work {
				v := process(ctx, k)
				mu.Lock()
				total += v
				mu.Unlock()
			}
		}(id)
	}
	for _, k := range records {
		work <- k
	}
	close(work)
	wg.Wait()
	return total
}

func main() {
	seqPath := recordTrace(func(ctx context.Context) { sequential(ctx) })
	defer os.RemoveAll(seqPath)
	poolPath := recordTrace(func(ctx context.Context) { pooled(ctx, 3) })
	defer os.RemoveAll(poolPath)

	fmt.Println("-- event count produced by the two setups --")
	fmt.Printf("%-10s %-25s %4d\n", "sequential", "record processing event", eventCount(seqPath, recordTag))
	fmt.Printf("%-10s %-25s %4d\n", "sequential", "worker start event", eventCount(seqPath, workerStartTag))
	fmt.Printf("%-10s %-25s %4d\n", "pooled", "record processing event", eventCount(poolPath, recordTag))
	fmt.Printf("%-10s %-25s %4d\n", "pooled", "worker start event", eventCount(poolPath, workerStartTag))
}

-- event count produced by the two setups --
sequential record processing event     12
sequential worker start event           0
pooled     record processing event     12
pooled     worker start event           3

PM8. process is called with the same function in both setups, and every call is wrapped in a trace.WithRegion block — this causes the trace to produce one start and one end event marked with recordTag. When six records are processed, this corresponds to twelve events (six starts, six ends) — regardless of the setup, because both setups process a total of six records.

In the pooled function, each worker makes the trace.Log call before starting to read from the channel — not inside the loop, right before the loop, once. This ordering is deliberate: if the tag were dropped again for every record, the worker start count would also depend on the number of records processed, and two separate pieces of information (how many workers there are, how many records were processed) would get mixed together. Dropping the tag only once, when a worker comes alive, keeps these two counts independent of each other.

Reading the Numbers

The table shows two different behaviors. record processing event is twelve in both setups — sequential or pooled, since the number of records processed is the same, the event count produced is the same too. This row shows what the trace does not change: the distribution of work itself does not change the total amount of work done.

worker start event, however, is zero in the sequential setup and three in the pooled setup. The sequential setup opens no extra goroutine at all, so it produces no worker start event; the pooled setup opens three workers, and each drops this tag once when it starts. This row explains what the trace shows: how many separate execution units actually ran — a human could also count that the for id := 0; id < workerCount; id++ loop in the source runs three times, but the trace reads this directly from the running program, with no need to examine the source separately.

Reading these two rows together gives information neither could give alone. If only record processing event were read, it would be seen that the two setups do the same work, but not how. If only worker start event were read, it would be seen that the pooled setup opens three workers, but not whether these three workers actually did any work — all three could have stayed idle and processed no record at all. Together, the two answer a third question: three workers opened and all six records were genuinely processed, none was lost, none was processed twice. This is proof that the channel-reading mechanism works correctly — by a different path from the “passed” decision a test gives, but the same kind of assurance.

The course’s opening split eleven facts into source, tool, and run; this lesson uses only the run out of those three classes — both the tagged regions and the worker starts only emerge once the program is actually run and traced.

Limiting Measurement: Collecting a Trace Changes Behavior

This lesson meets the course’s duration ban again from another angle. The trace.Start call begins recording every goroutine transition, every lock the program makes — this recording itself is not free; extra work rides on top of the program’s normal flow as every event is processed and written. This is why the behavior seen while tracing a program is always somewhat different from its untraced form: collecting a trace changes the program’s behavior.

This claim is not measured here — measuring it would require looking at duration, and duration is not written in any lesson of this course. Instead it is written down and justified with a sentence, just as the comparative measurement lesson justified the duration ban: collecting a trace is itself work, and that work is not zero. This is why the table above does not show how many events an untraced program produces, but how many events a traced program produces — the numbers must be read within this frame, without assuming the same behavior would continue with tracing turned off.

This limit belongs to the same family as the previous three lessons’ limits. A profile only saw the path that ran; escape analysis only showed this compiler’s decision; the allocation count taught that a number going down is not automatically an improvement. This lesson continues the same pattern: a measurement tool presents what it measures together with the act of measuring itself, and if the reader forgets this togetherness, they fall into a false sense of certainty. A trace changing behavior by collecting it is not a flaw of the trace tool — it is the unavoidable result of any observation tool becoming part of the system it observes.

The Scope of This Measurement

What a real production trace reads is far broader than the two tags in this lesson: when a scheduler stops one goroutine and runs another, how long a goroutine waits on a lock, when a garbage collection cycle starts — all of this sits inside the same trace and can be examined as a timeline with a trace viewer. This kind of examination usually looks for an answer to a specific problem: why did this request take longer than expected, which goroutine blocked which resource. These questions involve duration, which is why they are never asked in this course.

The method built in this lesson instead answers a narrow question: how many times did a specific event happen. This is a small slice of the information a real trace offers — it never sees the ordering in the timeline, the overlap, the wait duration. But even this narrow question cannot be answered by reading the source: someone reading the pooled function can see that three goroutines were opened, but they can only learn whether these three actually ran, whether they actually took work, by running and tracing it.

Summary

• An execution trace is a run fact, and in this lesson it was read as an event count; no goroutine number, timestamp, or stack trace was printed anywhere.
• Sequential and pooled setups processing the same six records produced the same number (twelve) of record processing events — the distribution of work did not change the total amount of work.
• The two setups produced a different number (zero, three) of worker start events — this difference comes from the trace directly showing how many separate execution units actually ran.
• The text the trace tool produced was never printed; only how many times the two chosen tags appeared was counted.
• Collecting a trace changes the program’s behavior; this lesson did not measure this, it wrote it down in a sentence and presented the numbers together with this limit.
• An execution trace’s raw content changes from run to run; this lesson therefore measured not the whole trace, but the part it tagged itself that came out stable.

Next Step

All four lessons of this topic learned something by running a program — profile, escape decision, allocation count, event count; all of them could only be read from a running program, and each had to admit that its own act of measuring changed the program a little. The next topic steps out of this ground entirely: a tool states which file enters the build, which platform is targeted, and what gets embedded into the binary without ever running the program — the run itself is no longer needed.