Record instructions retired alongside time in TIME_TRACE (depends on #928)

[quickbeam123]

A -tstat sweep is normally run many-ways parallel, and wall clock then measures the machine as much as the code: on the reference server, 120 concurrent jobs spread effective throughput from 1828 M instr/s at p10 to 4724 at p90, so a run at p10 takes 1.71x longer than the median for identical work. Ratios within one run survive that; per-node comparisons between runs do not.

Instruction counts do not have that problem. Measured on the same machine, a fixed workload retires 12000031 and 12000032 instructions across seven runs -- a spread of 0.0000%.

So each TIME_TRACE node now carries user-space instructions retired as well as elapsed time:

[root] (total: 39 ms, avg: 39 ms, cnt: 1, instr: 118 M)

Both are kept, deliberately. Part of that 2.6x throughput spread is genuine memory-boundedness rather than contention -- median throughput falls monotonically with peak memory, 4530 M instr/s under 64 MB down to 2672 at 256 MB-1 GB -- and an instructions-only trace would make a node that is slow because it is cache-missing look cheap. Time and instructions together give ns-per-instruction per node, which is what tells those two apart.

Reading the counter cheaply

Lib/Timer.cpp already opens a PERF_COUNT_HW_INSTRUCTIONS event but reads it with read(PERF_FD), which costs a syscall (~560ns measured) -- fine for the timer thread's 1ms limit check, hopeless for a scope entered ~10^9 times per run. The new Lib/PerfInstructions.hpp mmaps the same fd and reads the counter register directly with rdpmc under the metadata page's seqlock: 8.9ns measured, against 27.5ns for the clock_gettime the profiler already does per scope.

rdpmc reads the performance counter of whatever CPU the caller runs on, so it is only valid on the thread the event is attached to. Hence the split: ScopedTimer (main thread) takes the fast path, while printPretty -- which runs on timer_thread when a resource limit fires -- credits the still-open scopes using the new Timer::instructionCountAnyThread(), which goes through the fd. Everything degrades to "no measurement" rather than to a wrong number: non-x86, no cap_user_rdpmc, or an event not currently scheduled all yield -1, and the field then prints as "-" so the output format stays unconditional.

Two details worth knowing:

• reads are ordered so the instruction interval nests inside the time interval (clock first on entry, instructions first on exit), which keeps the cost of the clock read itself out of the instruction count;
• [root] is entered during static initialisation, long before the counter exists, so Timer::reinitialise() calls TimeTrace::rebaseInstructionCounters() once the event has been opened and reset. Without it the whole-run total would read 0.

instructionCountingAvailable() also refuses to report anything when the PMU is multiplexing this event (time_enabled != time_running), since the kernel then expects counts to be scaled, which would turn them into estimates and destroy the determinism that is the entire point.

Verified locally: unit tests 100/100, checks/sanity clean, output format correct. macOS has neither perf_event_open nor user-space PMU access, so the values themselves are NOT verified here -- they read "-". On Linux, check that [root]'s instr matches the independently-obtained "Instructions burned" statistics line (which reads the same event through read()), and that two -al-bounded runs of one problem agree to well under 0.1% per node while their times do not.

[MichaelRawson]

I will repeat my warning that this kind of DIY profiling may be misleading. Use something like perf record instead. But, with that caveat, this seems like an improvement.

[MichaelRawson]

It is rumoured GCC has an intrinsic for this, but I couldn't find anything quickly. In any event, this should be #ifdef-guarded for GCC/Clang so that __asm__ doesn't cause a compiler error.