mirror of
https://github.com/tangerineturtle1/NX2navi.git
synced 2026-11-15 19:19:58 -04:00
0472734008
The perf lines could not see pacing. In the 0.10.0 fresh session (nx2navi.1.log, 7,974,927 bytes) all 666 windows read "pacing 0%" and "bound: cpu" and all 70 slow-frame lines "pacing 0.0 drain 0.0", while 610 windows had a 16.x ms interval at fps_limit 60 under the game's own limiter. The pacer's wait happened where perf does not count it: vk_backend.c present_image's wait for the present thread to take the previous picture was untimed, perf_end drops waits on any thread but the presenting and replay ones (a game may acquire its window image on another), and the acquire's GPU wait was counted twice, as pacing around b->fence_wait and as a fence wait inside vk_sync_fence_wait (F-7-04). - host.h: PERF_HANDOFF, the presenting thread's wait to hand the present thread the next picture, timed in present_image from under pl (where pending is read) and kept in PresentJob.handoff_ns. perf_end_any counts a wait on any other guest thread into a sum that perf_present adds to the frame before ft_frame reads its parts. - nvn_api_obj.c nvnWindowAcquireTexture: the pacer's sleep is timed with perf_end_any; the GPU wait counts only as the fence wait it is; one line names the threads that acquire and present once the first present is known. - vk_backend.c present_main: the TRACE=present line adds the present call's time (vkQueuePresentKHR, under the queue lock, where an overlay's frame limiter sleeps) and the job's hand-off wait; with trace=perf, a line per 60 presents gives the present thread's blit and submit, paced wait, present call (avg, max), time past target and the hand-off. - perf.c: "handoff" in the window line's shares and the slow-frame line, "hand-off" in the worst-frame lines and as a cause of its own for frames over 25 ms and the stutter map. The "bound:" rule stays as it is until play-test numbers exist. - The cause list changes together: perf.c FT_C_* and ft_cause_name, stutter_map.c SM_CAUSES and cause_short, tests/stutter_hitch_check.c names[] (now sized from SM_CAUSES), and tools/stutter_map.py, whose cause and hitch patterns now take a hyphen. flight.c's frames.tsv gets a handoff_ms column (blocked_names checked against PERF_N), and tools/flight_view.py lists it. - tools/perf_summary.py reads the hand-off share, the present-thread lines and the TRACE=present lines, and prints percentiles of the present interval, paced wait, time past target, present call and hand-off. New tests/perf_summary_check.py makes lines with the runtime's format strings (checked against the C sources) and checks the percentiles, the window averages and the hand-off share, and that older lines without these fields still parse; tests/stutter_map_check.py gets a hand-off hitch and area cause, which the old patterns dropped. Diagnostics only: no wait, pacing or presentation change. Not reproduced before the change (it needs a game run with trace=perf). perf_summary_check, stutter_map_check, stutter_hitch_check, flight_flash_check and frame_step_check pass; every runtime file compiles with the dev flags after the host.h change, and the changed files add no -Wall -Wextra warnings. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
100 lines
6.8 KiB
Python
100 lines
6.8 KiB
Python
"""tools/stutter_map.py reads the lines runtime/stutter_map.c writes: lines made with the runtime's format strings
|
|
(copied below; keep them in step with stutter_map_init's neighbours stutter_frame and stutter_report) parse into the
|
|
areas, causes and pipelines they hold.
|
|
|
|
python tests/stutter_map_check.py
|
|
"""
|
|
import sys
|
|
import tempfile
|
|
from pathlib import Path
|
|
|
|
sys.path.insert(0, str(Path(__file__).resolve().parent.parent / 'tools'))
|
|
import stutter_map # noqa: E402
|
|
|
|
C_SOURCE = Path(__file__).resolve().parent.parent / 'runtime' / 'stutter_map.c'
|
|
|
|
|
|
def c_fmt(fmt, *args):
|
|
"""A C printf format with %llu, %u and %d as Python's %d."""
|
|
return fmt.replace('%llu', '%d').replace('%u', '%d') % args
|
|
|
|
|
|
def main():
|
|
src = C_SOURCE.read_text(encoding='utf-8')
|
|
# the format strings the parser depends on must still be in the runtime
|
|
for piece in ('stutter map (%s): %.1f min of play in %d areas; %llu hitches in play and %llu ',
|
|
'"after area loads; %llu long frames were a change of pace (the frames after them as long), not "',
|
|
'"hitches; in play by cause:"', 'stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute',
|
|
'"; %s %llu, %.1f ms avg"', '"), worst %.1f ms (frame %llu); over 25 ms %llu; after its "',
|
|
'"loads %llu; draws that met a pipeline missing %llu, a shader %llu, %.1f ms on the replay thread"',
|
|
'stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', '" (charged to %s)"',
|
|
'"stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:%s; an episode of %d frames to frame "',
|
|
'stutter map: %s %s/%s first met in %s: %llu draws met it missing, %llu its shader, %.1f ms on the ',
|
|
'"replay thread; usable after %.0f ms at most (%llu times); %s%s"'):
|
|
assert piece in src, f'runtime/stutter_map.c no longer has: {piece}'
|
|
lines = [
|
|
'[host] ' + c_fmt('stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', 1200, 75.2, 31.5, 7.1,
|
|
'Kakariko Village', '') + ' pipeline 24.0 replay 3.1 (charged to pipeline); draws that met a '
|
|
'pipeline missing: vertex 1a2b3c4d/5e6f7a8b 23.9 ms (skipped)',
|
|
'[host] ' + c_fmt('stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', 1300, 80.0, 60.0, 7.0,
|
|
'Kakariko Village', ', after its load') + ' unattributed 55.0 (charged to unattributed)',
|
|
# an episode of three frames: its head carries their summed time
|
|
'[host] ' + c_fmt('stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:%s; an episode of %d '
|
|
"frames to frame %llu, %.1f ms the first, the parts above the first frame's", 1400, 90.0, 274.0,
|
|
7.0, 'Kakariko Village', '', ' fence 77.1 replay 4.0 (charged to fence)', 3, 1402, 87.0),
|
|
# a cause with a hyphen in its name
|
|
'[host] ' + c_fmt('stutter: frame %llu at %.1f s, %.1f ms (frames about %.1f ms) in %s%s:', 1500, 95.0, 41.0, 7.0,
|
|
'Kakariko Village', '') + ' hand-off 33.0 (charged to hand-off)',
|
|
'[host] ' + c_fmt('stutter map (%s): %.1f min of play in %d areas; %llu hitches in play and %llu '
|
|
'after area loads; %llu long frames were a change of pace (the frames after them as long), not '
|
|
'hitches; in play by cause:', 'exit', 12.5, 2, 4, 1, 7) + ' pipeline 2 texture 1 hand-off 1',
|
|
'[host] ' + c_fmt('stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute', 'Kakariko Village', 10.0,
|
|
139.6, 4, 0.4)
|
|
+ c_fmt('; %s %llu, %.1f ms avg', 'pipeline', 2, 30.2) + c_fmt('; %s %llu, %.1f ms avg', 'texture', 1, 19.0)
|
|
+ c_fmt('; %s %llu, %.1f ms avg', 'hand-off', 1, 41.0)
|
|
+ c_fmt('), worst %.1f ms (frame %llu); over 25 ms %llu; after its '
|
|
'loads %llu; draws that met a pipeline missing %llu, a shader %llu, %.1f ms on the replay thread',
|
|
31.5, 1200, 1, 1, 4, 1, 40.2),
|
|
'[host] ' + c_fmt('stutter map: %s: %.1f min at %.0f fps; hitches %llu (%.2f a minute', '(before the first area)',
|
|
2.5, 120.0, 0, 0.0)
|
|
+ c_fmt('), worst %.1f ms (frame %llu); over 25 ms %llu; after its '
|
|
'loads %llu; draws that met a pipeline missing %llu, a shader %llu, %.1f ms on the replay thread',
|
|
0.0, 0, 0, 0, 0, 0, 0.0),
|
|
'[host] stutter map: 2 pipelines draws met missing: 1 that this install had recorded before (its prebuild had '
|
|
'not come to them), 1 new to it, 1 with a shader translated in play, 0 still translating when met; 0 not kept '
|
|
'(table full), 0 draws not seen by a present (ring full); the 40 that cost the most:',
|
|
'[host] ' + c_fmt('stutter map: %s %s/%s first met in %s: %llu draws met it missing, %llu its shader, %.1f ms on '
|
|
'the replay thread; usable after %.0f ms at most (%llu times); %s%s', 'vertex', '1a2b3c4d',
|
|
'5e6f7a8b', 'Kakariko Village', 3, 1, 30.0, 160.0, 1, 'new to this install',
|
|
', a shader translated in play'),
|
|
]
|
|
with tempfile.TemporaryDirectory() as d:
|
|
log = Path(d) / 'nx2navi.log'
|
|
log.write_text('\n'.join(lines) + '\n', encoding='utf-8')
|
|
block, hitches = stutter_map.read_log(log)
|
|
assert block and block['head'][0] == 'exit' and block['head'][3] == '4', block and block['head']
|
|
a = block['areas'][0]
|
|
assert a['name'] == 'Kakariko Village' and a['hitch'] == 4, a
|
|
assert a['causes'] == {'pipeline': 2, 'texture': 1, 'hand-off': 1}, a
|
|
assert a['pmiss'] == 4 and a['smiss'] == 1 and a['load'] == 1 and a['over25'] == 1, a
|
|
assert block['areas'][1]['causes'] == {}, block['areas'][1]
|
|
assert block['sum'] == (2, 1, 1, 1, 0), block['sum']
|
|
p = block['pipes'][0]
|
|
assert p['v'] == '1a2b3c4d' and p['f'] == '5e6f7a8b' and p['ready'] == 160 and p['misses'] == 3, p
|
|
assert p['state'].startswith('new to this install'), p
|
|
assert len(hitches) == 4 and hitches[0]['cause'] == 'pipeline' and hitches[1]['load'], hitches
|
|
assert hitches[2]['ms'] == 274.0 and hitches[2]['cause'] == 'fence' and not hitches[2]['load'], hitches[2]
|
|
assert hitches[3]['cause'] == 'hand-off', hitches[3]
|
|
out = Path(d) / 'map.md'
|
|
stutter_map.report([log], out)
|
|
text = out.read_text(encoding='utf-8')
|
|
assert block['head'][5] == '7' and block['head'][6] == ' pipeline 2 texture 1 hand-off 1', block['head']
|
|
assert '7 long frames left out' in text and '**4 hitches in play**' in text and '| Kakariko Village | 10.0 | 140 |' in text, text
|
|
assert 'hand-off 1' in text, text
|
|
print('stutter_map_check: ok')
|
|
return 0
|
|
|
|
|
|
if __name__ == '__main__':
|
|
sys.exit(main())
|