Repository navigation
Conversation
DTO_COLLECT_STATS kept one global table that every thread updated with
atomic adds, so the cost of collecting grew with the thread count: a
4 KiB memcpy on the CPU path cost 55 ns more with stats on at one
thread and 2.6 us more at 32 threads. Each thread now counts in its own
block, mapped when the thread first records a call and folded into a
retired total when the thread exits; output sums the live blocks and
the retired total. Stats now cost about 40 ns per call (the two clock
reads) at any thread count:
extra cost per call, CPU path 1 thr 4 thr 16 thr 32 thr
4 KiB, before +55 +357 +1319 +2612 ns
4 KiB, after +44 +46 +42 +37 ns
The histogram's 512 linear 4 KiB buckets, the last of which held
everything from 2 MiB up, become log-scaled: under 64 bytes, then four
buckets per power of two up to 4 GiB, then one for anything larger.
New settings:
DTO_STATS_INTERVAL_MS=N a sampler thread writes what happened in
each N ms; the records add up to the summary
DTO_STATS_FORMAT=json JSON Lines: interval and summary records with
calls/bytes/ns per op and path, failures,
histogram, and the configuration at exit
DTO_STATS_FILE=...%p... %p becomes the process ID
DTO_STATS_FILE is now appended to rather than truncated, so a forked
or exec'd child's records don't overwrite its parent's; each record
carries its pid. After fork the child starts with empty counts, and a
%p file is reopened under its own pid. The old dto_stats_log() wrote
each line twice when DTO_LOG_FILE was set and reused a consumed
va_list; it is gone, along with the TRACE log level that turning on
stats forced.
Adds tests/test_stats.py (ctest -R stats) with a workload of known
calls: totals and buckets, intervals summing to totals, 200
short-lived threads all counted and their blocks unmapped, fork,
%p, and text output.
The stats rework uses thread keys, a sampler thread and its condition variable. Before glibc 2.34 those functions are in libpthread, not libc, so preloading libdto into a program that doesn't link libpthread itself (sh, true, most single-threaded tools) failed at load time: true: symbol lookup error: libdto.so: undefined symbol: pthread_key_create Link libdto with pthread in CMake and the Makefile (an empty stub on newer glibc), and check in the stats test that stats work in a program without libpthread. Seen on RHEL 8 (glibc 2.28); Ubuntu 24.04 (2.39) is not affected.
- stats_fork_child() called pthread_setspecific(stats_key, NULL) even when stats were off and the key had never been created, i.e. on key 0, which belongs to whichever library created it first. Only touch the key when it exists. - sampler_lock was not held across fork(), so a child could inherit it locked by the parent's sampler thread and hang in its first stats_start_sampler(). Take it in the prepare handler with the other two and release it in parent and child. - stats_stop_sampler() reset sampler_started, so a thread whose first counted call landed after cleanup_dto() restarted the sampler during process exit, writing to closed descriptors. Set stats_shutdown in cleanup_dto() and check it before starting the sampler. - stats_flush() gave up on EINTR and EAGAIN and discarded the rest of the record. Retry on EINTR and poll() on EAGAIN. - The 64 KiB output buffer was smaller than a worst-case JSON summary, so a record could go out in two write()s and interleave with another process's in a shared O_APPEND file. Make it 256 KiB. - DTO_STATS_INTERVAL_MS accepted negative, non-numeric and absurd values silently; reject them with an error like DTO_STATS_FORMAT does.
"dtoctl --stats-run[=DIR] [--repeat=N] [--perf[=PERF]] prog" runs the program CPU-only (DTO_USESTDC_CALLS=1) and then with DSA, N times each, alternating, with DTO_STATS_FORMAT=json and each run's stats in its own file in DIR. dtoctl records each run's wall time, user and system CPU time (wait4, so including children) and exit status in DIR/runs.jsonl, then runs dto-stats-report on DIR. dto-stats-report (Python 3, standard library only) sums the stats of every process a run started, takes medians over the runs, and prints: wall, CPU and mem* time each way; Amdahl's law from f (share of the CPU-only run's CPU time in mem* calls) and s (mem* speedup per byte), 1 / ((1 - f) + f / s), against the measured speedup and the 1 / (1 - f) limit; each operation and the sizes with the most time; and notes: no call reached DSA (and why), runs did different amounts of work, sizes where DSA was slower (with a DTO_MIN_BYTES to try), runs that failed or wrote no stats. --json prints the numbers instead. With --perf, one more run each way goes through "PERF record -e cpu-clock" (cpu-clock works without hardware counters, and on a test kernel here cycles hardly sampled). perf runs dtoctl again, so DTO is preloaded into the program and not into perf. The report splits each profile into copies, memset, memcmp, CRC, kernel copies, DTO itself and the rest, and notes mem* time DTO did not intercept and CRC time DSA could take. Where libc has no symbol table (Ubuntu), perf shows its memcpy as an address; on the machine that made the profile the report asks its own libc, through dlsym, which implementation of each function this CPU uses, and places samples by address, after checking the profile's libc has the same build ID. Ctrl-C and Ctrl-\ go to the program, as with system(); a run that fails stops the rest, and dtoctl exits with its status. Also adds --stats-format and --stats-interval for DTO_STATS_FORMAT and DTO_STATS_INTERVAL_MS, and documents them with --stats-run in the man page, README and TESTING.md. Tests: test_dtoctl.sh checks the new options, the --stats-run plan (--dry-run), a real stats run of a shell command and a failing one; tests/test_stats_report.py checks the report's arithmetic on made-up runs with known answers, sorts made-up perf lines, and finds memcpy, memset and memcmp by address in this machine's libc.
The first example reused 256 KiB buffers that stayed in the core's L2, the one case where the CPU beats DSA, and pre-faulted them with MAP_POPULATE, which on gnr-qual1's kernel makes about a quarter of DSA calls 5x slower. Replace it with a run that copies out of a 1 GiB buffer, pinned to the DSA's node: 1.20x measured, 1.21x predicted.
- A failed profiled run (perf not permitted, or a perf shim without a matching kernel perf) ended --stats-run with perf's status and no report, although every timed run had completed. Report them and say the profile is missing; the report's note no longer claims later runs did not happen when the failed run is a profiled one. - The report mixed a mean with medians: mem* time and bytes were averaged over the runs while the CPU and wall times were medians, so one preempted CPU-only run could push f past 100% or make "outside mem* calls" negative. Take the CPU time, mem* time and histogram from the run with the median CPU time; the wall time stays the median. The test gives its outlier run three times the mem* time to cover this. - restore_preload() put back the caller's whole LD_PRELOAD, so with a libdto exported in the caller's shell perf and the report ran with it, and the report appended a JSON summary to its own output. Restore the list without libdto entries. - libdto expands only %p in DTO_STATS_FILE, so refuse %p in the stats directory rather than any %, and check before creating the directory. - The shell test's "stats run succeeds" assertion needs python3 for the report; guard it like the output check.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Stacked on #38 (dtoctl) and #41 (stats). Only the last commit,
dtoctl: add --stats-run to measure the speedup from DSA, is new here. I'll rebase once those are merged.dtoctl --stats-runanswers two questions: how much faster is a program with DSA, and how much faster could it be? It runs the program CPU-only (DTO_USESTDC_CALLS=1) and then with DSA, collecting #41's JSON stats from each run.dto-stats-reportthen compares the runs using Amdahl's law. With--perf, it also profiles one run each way and shows where the CPU time went.This is gnr-qual1 with one DSA (wq0.0). The test program is single-threaded: it copies, sets and compares 256 KiB buffers that stay in cache, computes a software CRC32C, and does other work. The CPU-only run spent f = 31.5% of its CPU time in mem* calls, and those calls ran at s = 0.38x with DSA. Amdahl's law therefore predicts 0.66x, and the measured speedup was 0.63x. The remaining gap shows up on its own row: time outside mem* calls went from 663 to 748 ms. The profile shows the cost of DSA here: 34% of the DSA run's CPU time is DTO busy-polling.
What it does
dto-stats-<date>-<time>. It runs the program N times each way (--repeat), alternating the two modes so that drift affects both. For each run it records wall time, user+sys CPU time (wait4, so children are included) and the exit status inruns.jsonl, then runsdto-stats-report DIR.system(). A run that fails stops the rest, and dtoctl exits with its status.--dry-runprints the plan without running anything.--perf[=PERF]adds one more run each way underPERF record -e cpu-clock -F 999.cyclesgave about 10 samples a run.perf record -- dtoctl -l LIB -- prog), so DTO is preloaded into the program but not into perf.--jsonprints the numbers instead of the tables. It:stdc_onlyat exit), or every call belowmin_bytes;DTO_MIN_BYTESto try when there is a clear crossover;_exit()as dash does);.symtab, so perf shows__memmove_avx512_unaligned_ermsas a bare address. On the machine that made the profile, the report uses dlsym in its own process to find which memcpy/memset/memcmp implementations this CPU uses. It then places samples by address, but only after checking the profile's libc has the same build ID. Without this, the libc rows of the profile above would be unnamed.--stats-formatand--stats-intervalsetDTO_STATS_FORMATandDTO_STATS_INTERVAL_MS.Limits
sudorun needsudo dto-stats-report. The report says this instead of failing with a traceback.Testing
ctest -R "dtoctl|stats|functional"passes:tests/test_dtoctl.shchecks:--dry-runplan;runs.jsonl, the saved stats and the report;tests/test_stats_report.py(newstats-reportctest; needs neither DSA nor perf) checks:Running a stats run on RHEL 8 turned up a bug in #41: libdto wasn't linked with pthread. The fix is now on #41 (
stats: link libdto with pthread) and included here.