Skip to content

Time Profile: Ignore an END_IDLE with no BEGIN_IDLE - #173

Merged
ritvikrao merged 3 commits into
mainfrom
logreader-unmatched-end-idle
Oct 27, 2026
Merged

ritvikrao merged 3 commits into
mainfrom
logreader-unmatched-end-idle

Conversation

@ritvikrao

Copy link
Copy Markdown
Collaborator

Problem

When a PE is already idle when tracing begins, its log starts with an END_IDLE that has no BEGIN_IDLE before it. On such traces, Time Profile shows the whole run as overhead (solid black). Timeline is unaffected and shows the entry methods normally.

LogReader keeps a processing counter per PE, and addToInterval drops all time while that counter is <= 0. The unmatched END_IDLE takes the counter to -1. After that it only moves between -1 and 0, so every later idle and entry-method interval on the PE is dropped. Time Profile then computes overhead as interval − 0 idle − 0 work. Timeline uses its own parser, so it never hits this.

Seen on a Reconverse Barnes-Hut trace on 8 nodes × 15 PEs: all 120 PEs start with an unmatched END_IDLE. The same program on 1 node × 120 PEs starts with BEGIN_IDLE and was unaffected.

Fix

The read loop now tracks whether an idle period is open and skips an END_IDLE when none is. Unmatched END_PROCESSING events (isProcessing) are already handled the same way.

Testing

The repo has no unit tests, so I used a small headless harness. It loads each trace and runs every PE through the same LogReader.read() call the Time Profile uses, over the whole run in 10 ms intervals. Percentages are shares of total PE time.

Trace Build PEs with entry time Entry (%) Idle (%) Overhead (%)
Barnes-Hut, 8 nodes × 15 PEs main 1 / 120 0.0 0.0 100.0
Barnes-Hut, 8 nodes × 15 PEs this PR 120 / 120 53.3 33.1 13.6
Barnes-Hut, 1 node × 120 PEs main and this PR 120 / 120 14.7 82.0 3.3
test/hello (4 PEs) main and this PR 4 / 4 2.6 14.6 82.7

Traces that were already correct give identical numbers. Most of the 13.6% overhead left on the 8 × 15 trace is the stretch before tracing begins (the first 410 ms of 3.4 s, 12.1%), which counts as overhead in both runs. The idle time before the first unmatched END_IDLE is also counted as overhead, since the log doesn't record when it started.

Not checked: the GUI itself (the harness calls the same read()), and the Overview tool, which also creates a LogReader.

🤖 Generated with Claude Code

A PE that is already idle when tracing begins logs an END_IDLE with no
BEGIN_IDLE before it. LogReader passed it on anyway, which left its
processing counter at -1. From then on the counter only moved between
-1 and 0, and addToInterval drops all time while it is <= 0, so every
later idle and entry-method interval on that PE was thrown away. Time
Profile then showed the whole run as overhead (interval minus zero idle
minus zero work), while Timeline, which has its own parser, showed the
entry methods normally.

Track whether an idle period is open in the read loop and skip an
END_IDLE when none is, the same way an END_PROCESSING with no open
entry method is already skipped.

Seen on a Reconverse Barnes-Hut trace on 8 nodes x 15 PEs, where all
120 PEs start with an unmatched END_IDLE; the same program on 1 node x
120 PEs starts with BEGIN_IDLE and was unaffected.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
lvkale
lvkale previously approved these changes Oct 27, 2026

@lvkale lvkale left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving. The diagnosis matches the code: the per-PE processing counter is driven by BEGIN/END_IDLE and BEGIN/END_PROCESSING, addToInterval only accumulates while it is positive, and an unmatched END_IDLE pins it at -1/0 for the rest of the PE. Skipping the END_IDLE is the right tolerance, and it parallels the existing unmatched-END_PROCESSING handling. Skipping intervalCalc also skips fillToInterval, which is harmless since the next event's fill catches up with the counter at zero.

Independent check: I built this branch and ran every PE of a trace through the same LogReader.read() call Time Profile uses, on main and on this branch.

Trace main this PR
test/hello, unmodified 4/4 PEs, entry 2.5%, idle 14.6% identical
hello with the first BEGIN_IDLE deleted on PEs 1 and 2 PEs 1 and 2 report zero entry and zero idle 4/4 PEs restored; idle short by only the deleted span
hello with a mid-run BEGIN_IDLE deleted on PE 3 PE 3 loses everything after the gap PE 3 fully restored

The mid-run case shows the fix is more general than the title: any unmatched END_IDLE, not only a leading one, used to zero the rest of the PE. Unmodified traces give identical numbers.

For the record, none of the .log traces on my machine (120-PE reconverse FoF3, all logs; 896-PE Frontier FoF3, first idle event of every log) start with END_IDLE, so the 8x15 Barnes-Hut trace is the only known instance. That points at a reconverse startup-ordering question (tracing initialized after the scheduler already went idle) worth raising on the charm side, independent of this fix.

Two non-blocking notes inline.

Comment thread src/projections/analysis/LogReader.java Resolved
Comment thread src/projections/analysis/LogReader.java Resolved
A BEGIN_IDLE while an idle period is already open incremented the
processing counter twice, so the PE kept booking time as idle after the
matching END_IDLE. Close the open period first, the same way
BEGIN_PROCESSING closes an open entry method with a synthetic
END_PROCESSING. No trace is known to produce this, but a duplicated
BEGIN_IDLE in test/hello's PE 0 raised idle from 14.6% to 20.8% before
this change and leaves it at 14.6% after.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

@lvkale lvkale left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Re-approving after 71cce6c and the merge of main. Verified the new guard independently: a copy of test/hello with one BEGIN_IDLE duplicated on PE 0 gives idle 20.8% on main and 14.6% with this branch (same as the unmodified trace), and the leading and mid-run unmatched END_IDLE cases from my first review still come out right. Agreed on leaving the pre-BEGIN_COMPUTATION stretch as overhead and taking the BEGIN_IDLE-at-trace-start question to the runtime.

@ritvikrao
ritvikrao merged commit 0e1b48e into main Oct 27, 2026
2 checks passed
@ritvikrao
ritvikrao deleted the logreader-unmatched-end-idle branch October 27, 2026 01:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants