Correlating six event boundaries across direct and queued calls

Follow one event through a caller and a worker. Add a delay in two different places and use the recorded markers to find where the extra time first appears.

This lab has two versions of the same flow. In direct mode, one thread performs everything. In queued mode, one thread receives events and another takes them from a queue. The classes are simply Dispatcher, Worker, and TraceBuffer; no external service or application framework is needed.

Before you start#

Use Linux, a C++11 compiler, and Python 3.7 or newer. GDB is optional. Complete timing and waiting first if elapsed duration and entry interval are unfamiliar.

A sequence ID is a number attached to one event. It lets us recognize that event at several points, even after another thread handles it. A queue lets the receiving thread hand work to a consumer thread.

1. Get the two files and build#

Choose one workspace. If you have the repository, start at its root and run:

bash

cd examples/event-pipeline

Website-only readers can instead create an empty directory:

bash

mkdir -p ~/execmap-labs/event-pipeline
cd ~/execmap-labs/event-pipeline

Download event_pipeline.cpp and this lab's analyze.py into it. Keep this directory separate from the timing lab: the two analyzers have the same filename but expect different records.

In your chosen directory:

bash

ls event_pipeline.cpp analyze.py
mkdir -p build results
g++ -std=c++11 -g3 -O0 -fno-omit-frame-pointer -Wall -Wextra -Wpedantic -pthread event_pipeline.cpp -o build/event_pipeline
sha256sum event_pipeline.cpp analyze.py build/event_pipeline > results/inputs.sha256

The last command records file identities for repeatability. It writes to a file, so no terminal output from that command is expected.

2. Follow the direct call first#

bash

./build/event_pipeline direct baseline 8 direct-baseline results/direct.csv
python3 analyze.py results/direct.csv --mode direct --expected-count 8

The first command means: use direct calls, add no artificial delay, process 8 events, label the run direct-baseline, and save its CSV. A run label distinguishes captures that reuse sequence numbers.

The analyzer should begin with:

text

PASS: run=direct-baseline count=8 mode=direct

It then prints one summary line for each sequence number. Each event has six markers:

text

RECEIVED → DISPATCH_ENTER → BEFORE_CALL → WORK_ENTER → WORK_EXIT → AFTER_CALL

Read the names as a small story: an event arrives, the dispatcher starts handling it, the dispatcher is about to call the worker, the worker enters and exits, and the dispatcher resumes after the call. Eight events produce 48 records.

In this mode, every marker for an event has the same TID. That is the operating-system thread ID. You can open results/direct.csv in a text editor to see it directly.

3. Move receipt and processing onto different threads#

bash

./build/event_pipeline queued baseline 8 queued-baseline results/queued.csv
python3 analyze.py results/queued.csv --mode queued --expected-count 8

Here the source thread records RECEIVED and puts the event into a queue. The consumer thread records the remaining five markers. They have different TIDs, but keep the same run label and sequence number for the same event.

The consumer's dispatcher still calls its worker synchronously: it waits for that function to return. The thread handoff happened earlier, at the queue. This is why a queued application can contain ordinary synchronous calls too.

Your checkpoint: locate one sequence in the CSV and explain the TID change. If you grouped records only by TID, you would split this one event into two incomplete pieces.

4. Add a gap before an event arrives#

bash

./build/event_pipeline direct source-gap 8 source-gap-run results/source-gap.csv
python3 analyze.py results/source-gap.csv --mode direct --expected-count 8

The source normally waits 10 ms between iterations. Before sequence 3, this scenario adds another 30 ms sleep.

Find sequence 3 in the report. Its source_interval_ms should show the longer interval between receipts. The worker's entry interval can grow too, because that event reached the whole flow later. Its own call can still be short.

This is a controlled test: you know where the wait was inserted. On a real application, a large receipt interval would narrow the investigation to before that marker, but would not identify the ultimate hardware or external-source cause by itself.

5. Add a wait inside the caller#

bash

./build/event_pipeline direct dispatch-wait 8 dispatch-wait-run results/dispatch-wait.csv
python3 analyze.py results/dispatch-wait.csv --mode direct --expected-count 8

For sequence 3, the dispatcher now waits 30 ms after BEFORE_CALL but before worker entry. Look at call_transition_ms for that sequence. It should contain the added wait, while work_elapsed_ms can stay small.

Now repeat with the queue:

bash

./build/event_pipeline queued dispatch-wait 8 queued-wait-run results/queued-wait.csv
python3 analyze.py results/queued-wait.csv --mode queued --expected-count 8

While the consumer waits, the producer can receive later events. Those events may spend longer between receipt and dispatcher entry, visible as receive_to_dispatch_ms.

Your checkpoint: distinguish “the worker itself took longer” from “work waited before the worker started.” A large caller-to-worker interval alone does not prove scheduler delay; in this experiment the caller deliberately sleeps there.

6. Read only the fields needed for your question#

Start with four report fields:

source_interval_ms: how long since the previous event was received?
receive_to_dispatch_ms: how long from receipt until handling began?
call_transition_ms: how long from before-call until worker entry?
work_elapsed_ms: how long between worker entry and exit?

The remaining fields fill in the smaller boundaries: dispatch_prepare_ms is dispatcher entry to before-call, return_transition_ms is worker exit to after-call, and caller_elapsed_ms covers before-call to after-call. work_entry_interval_ms compares the starts of successive worker calls.

A direct call blocks the source loop until it returns, so a caller-side wait can also delay a later receipt. Compare the sequence number and event order rather than assigning a root cause from one large interval.

If the report is rejected#

Unexpected header: confirm you are using the event-pipeline analyzer, not the timing lab's analyzer.

Missing or mixed events: wait for the program to finish and analyze one complete file. Keep a separate run label and output file per experiment; do not concatenate captures.

Thread relationship does not match mode: pass --mode direct for a direct recording and --mode queued for a queued one. The analyzer checks that relationship instead of guessing it.

Timings differ from a nominal 10 or 30 ms: other load can delay any step. Look for the controlled change and its location rather than exact millisecond equality.

Further details and verification#

Each thread has its own TraceBuffer. Buffers and queue storage are allocated before recording, merged after the consumer joins, and written afterward. Clock reads, locks, wakeups, and buffering still affect timing. This is a single-producer, single-consumer, FIFO example without recursion.

The analyzer checks all six ordered events, contiguous sequence numbers, one run ID, monotonic clocks, and the selected TID relationship. All elapsed timestamps use the same process's steady clock. CPU counters belonging to different threads could not be subtracted in the same way. The receipt-to-dispatch interval includes application queueing and scheduling opportunities; it is not a pure runqueue-delay measurement.

From the repository root on Linux:

bash

python3 scripts/verify-debugging-labs.py --require-linux --gdb

This checks all six mode/scenario combinations, invalid traces, known synthetic intervals, and the published C++ GDB session. Reports go to output/debugging-validation/. See the validation record for actual tool coverage; perf/BPF and remote debugging have separate evidence.

Keep one sequence's six markers and explain which boundary changed in each scenario. Continue with C++ call-chain debugging to inspect the objects, or thread counters to observe a task without tracing.

Sources#

C++ steady_clock defines the clock contract.
Linux gettid defines OS thread identity.
GDB C++ expressions supports the follow-up member inspection.