Skip to content

Commit 53283b5

Browse files
committed
Sound: compile vertex shaders without the big lock; fuller session recording
A session recording showed the sound threads waiting 50-64 ms for the big lock between the loading screen and the race: the game thread was compiling a new vertex shader (and its HD capture kernel) synchronously in metal_register_vs, 214 ms in all over the session, holding the lock. The compile now runs with the lock released and the results are stored once it is back (VSCOMPILELOCK=1 keeps the old behaviour). Cmd+Shift+D captures a burst of consecutive frames (CAPBURST, default 8; the draw list for the first), since flicker only shows between frames. tools/session.sh opens the newest bundle (an old out/personal copy won over a fresh ./pack.sh) and records much more by default: the game's own log with timestamps on the PERFLOG clock, sound state/gaps, sound.csv and the played sound, timer/thread/lock and file logs, a GPU pass profile. "all" turns every HD picture and reflection option on; SESSION_LIGHT=1 is the old recording.
1 parent 3af301d commit 53283b5

3 files changed

Lines changed: 78 additions & 21 deletions

File tree

‎runtime/metal.m‎

Lines changed: 42 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -57,9 +57,9 @@ static void dump_init(void){
5757
* ~/Library/Logs/NFSU2/). For scenes the user reaches but automated tests
5858
* can't produce (e.g. the end of a career race). */
5959
static _Atomic int g_dump_req;
60-
static long g_dump_req_f = -1;
60+
static long g_dump_req_f = -1, g_dump_req_end = -1; /* Cmd+Shift+D: frames [f, end] */
6161
static int dump_wanted(long f){
62-
if (f == g_dump_req_f) return 1;
62+
if (g_dump_req_f >= 0 && f >= g_dump_req_f && f <= g_dump_req_end) return 1;
6363
for (int i = 0; i < g_dump_n; i++) if (g_dump_want[i] == (int)f) return 1;
6464
return 0;
6565
}
@@ -4491,35 +4491,58 @@ void metal_set_ps(int psid, const float *c32){
44914491
* The game's own bytecode is translated to MSL and compiled here. */
44924492
#define MAXVSF 512
44934493
static id<MTLFunction> g_vsfn[MAXVSF];
4494+
/* The compile runs WITHOUT the big lock (guest_blocking_begin): a new shader is
4495+
* compiled synchronously on the game thread when it is first drawn, and with the
4496+
* HD capture kernel that took 50-110 ms when a race started (2026-11-04 session:
4497+
* the sound threads waited 50-64 ms for the lock -> the sound stuttered between
4498+
* the loading screen and the race). Nothing here touches guest memory; the
4499+
* results are stored after the lock is back. VSCOMPILELOCK=1: keep the lock. */
44944500
void metal_register_vs(int vsid, const char *msl){
44954501
if (vsid <= 0 || vsid >= MAXVSF || !msl || !g_dev || g_vsfn[vsid]) return;
44964502
@autoreleasepool {
44974503
NSString *src = [kPrelude stringByAppendingString:
44984504
[NSString stringWithUTF8String:msl]];
44994505
NSError *err = nil;
4506+
int guest_blocking_begin(void); void guest_blocking_end(void);
4507+
static int keep = -1; if (keep < 0) keep = ENVC("VSCOMPILELOCK") != NULL;
4508+
int yielded = keep ? 0 : guest_blocking_begin();
4509+
id<MTLFunction> vfn = nil;
4510+
#if NFS_ENHANCED
4511+
id<MTLComputePipelineState> vsk = nil; NSError *ke = nil; int want_k = 0;
4512+
#endif
45004513
struct timespec _c0; if (g_perflog) clock_gettime(CLOCK_MONOTONIC, &_c0);
45014514
id<MTLLibrary> lib = [g_dev newLibraryWithSource:src options:nil error:&err];
45024515
if (g_perflog){ struct timespec _c1; clock_gettime(CLOCK_MONOTONIC, &_c1);
45034516
perflog_event(PL_VS, (uint64_t)(_c1.tv_sec - _c0.tv_sec) * 1000000000ull + (uint64_t)_c1.tv_nsec - (uint64_t)_c0.tv_nsec, 0); }
4517+
char nm[32];
4518+
if (lib){
4519+
snprintf(nm, sizeof nm, "vs_%d", vsid);
4520+
vfn = [lib newFunctionWithName:[NSString stringWithUTF8String:nm]];
4521+
#if NFS_ENHANCED
4522+
if (vsid < HD_MAXVSI && hd_rt_on()){
4523+
want_k = 1;
4524+
snprintf(nm, sizeof nm, "vsk_%d", vsid);
4525+
id<MTLFunction> kf = [lib newFunctionWithName:[NSString stringWithUTF8String:nm]];
4526+
if (kf) vsk = [g_dev newComputePipelineStateWithFunction:kf error:&ke];
4527+
}
4528+
#endif
4529+
}
4530+
if (yielded) guest_blocking_end();
45044531
if (!lib){
45054532
static int shown = 0;
45064533
if (shown < 5){ shown++;
45074534
fprintf(stderr, "vertex shader %d could not be compiled: %s\n", vsid,
45084535
err ? [[err localizedDescription] UTF8String] : "?"); }
45094536
return;
45104537
}
4511-
char nm[32]; snprintf(nm, sizeof nm, "vs_%d", vsid);
4512-
g_vsfn[vsid] = [lib newFunctionWithName:[NSString stringWithUTF8String:nm]];
4513-
if (!g_vsfn[vsid])
4538+
g_vsfn[vsid] = vfn;
4539+
if (!vfn)
45144540
fprintf(stderr, "vertex shader %d: function not found\n", vsid);
45154541
#if NFS_ENHANCED
4516-
if (vsid < HD_MAXVSI && hd_rt_on()){
4517-
snprintf(nm, sizeof nm, "vsk_%d", vsid);
4518-
id<MTLFunction> kf = [lib newFunctionWithName:[NSString stringWithUTF8String:nm]];
4519-
NSError *ke = nil;
4520-
if (kf) g_hd_vsk[vsid] = [g_dev newComputePipelineStateWithFunction:kf error:&ke];
4521-
if (!g_hd_vsk[vsid]) fprintf(stderr, "[HD] capture kernel vs_%d could not be built: %s\n", vsid,
4522-
ke ? [[ke localizedDescription] UTF8String] : "no function");
4542+
if (want_k){
4543+
g_hd_vsk[vsid] = vsk;
4544+
if (!vsk) fprintf(stderr, "[HD] capture kernel vs_%d could not be built: %s\n", vsid,
4545+
ke ? [[ke localizedDescription] UTF8String] : "no function");
45234546
}
45244547
#endif
45254548
}
@@ -6954,13 +6977,17 @@ + (unsigned long long)_d1.tv_nsec - (unsigned long long)_d0.tv_nsec);
69546977
{ static long yk = -2; if (yk == -2){ const char *e = ENVC("YAKALAKARE"); yk = e ? atol(e) : -1; }
69556978
if (fno_pre == yk) atomic_store(&g_dump_req, 1); } /* test of the shortcut */
69566979
if (atomic_exchange(&g_dump_req, 0)){
6957-
g_dump_req_f = fno_pre;
6980+
/* a burst of consecutive frames (CAPBURST, default 8): flicker
6981+
* only shows between frames; the draw list is written for the first */
6982+
static long burst = -1;
6983+
if (burst < 0){ const char *e = ENVC("CAPBURST"); burst = e ? atol(e) : 8; if (burst < 1) burst = 1; if (burst > 64) burst = 64; }
6984+
g_dump_req_f = fno_pre; g_dump_req_end = fno_pre + burst - 1;
69586985
if (!g_dump_n){ const char *pl = getenv("PERFLOG"), *h = getenv("HOME");
69596986
if (pl && *pl) snprintf(g_dump_dir, sizeof g_dump_dir, "%s", pl);
69606987
else snprintf(g_dump_dir, sizeof g_dump_dir, "%s/Library/Logs/NFSU2", h ? h : "/tmp"); }
6961-
fprintf(stderr, "capture: frame %ld (Cmd+Shift+D) -> %s\n", fno_pre, g_dump_dir);
6988+
fprintf(stderr, "capture: frames %ld-%ld (Cmd+Shift+D) -> %s\n", fno_pre, g_dump_req_end, g_dump_dir);
69626989
}
6963-
int dumpnow = (g_dump_n || g_dump_req_f == fno_pre) && dump_wanted(fno_pre);
6990+
int dumpnow = (g_dump_n || (g_dump_req_f >= 0 && fno_pre >= g_dump_req_f && fno_pre <= g_dump_req_end)) && dump_wanted(fno_pre);
69646991
/* GLYPHDUMP: screen box + UV of every quad.
69656992
* Goal: decode the TEXT the game writes and read its state. */
69666993
if (ENVC("GLYPHDUMP") && dumpnow && rb >= 0){

‎runtime/overrides.c‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -567,8 +567,10 @@ void sub_0050d510(CPU *c){
567567
for (const char *t2 = tmp; *t2 && o < sizeof out - 2; t2++) out[o++] = *t2;
568568
}
569569
out[o] = 0;
570-
fprintf(stderr, " [game] %s%s", out,
571-
(o && out[o-1] == '\n') ? "" : "\n");
570+
/* seconds on the PERFLOG clock (perflog.c), to line up with its CSVs */
571+
{ uint64_t perflog_now_us(void);
572+
fprintf(stderr, " [game %.3f] %s%s", perflog_now_us() / 1e6, out,
573+
(o && out[o-1] == '\n') ? "" : "\n"); }
572574
/* Inside SwitchFEngPackages ebx = the front-end package manager
573575
* ("this"). printf is called exactly at that point, so we catch the
574576
* pointer here for free; needed to force the transition. */

‎tools/session.sh‎

Lines changed: 32 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -3,22 +3,37 @@
33
#
44
# ./tools/session.sh normal build
55
# ./tools/session.sh hd HD build
6+
# ./tools/session.sh hd all HD build with every HD picture / reflection option on
7+
#
8+
# Besides PERFLOG every session records (light enough to play with):
9+
# game log [game t] GAMELOG (front-end transitions, on the PERFLOG clock)
10+
# sound SNDSTAT/SNDGAP lines, sound.csv (every mixer callback),
11+
# sound_out.raw (what was played: s16le 44100 Hz stereo)
12+
# timing / threads TIMELOG, THREADLOG, GILLOG=20 (lock holds > 20 ms), [timer]
13+
# files FILEOPLOG (opens/closes; loads between menus)
14+
# GPU PASSPROF every 120 frames -> passprof.csv, MATLOG, TEXUPSAY
15+
# SESSION_LIGHT=1 PERFLOG only, as before
616
#
717
# The game starts with recording on (PERFLOG); play normally, quit the game when
818
# done. At the same time powermetrics writes CPU/GPU watts once a second (the
919
# admin password is asked once; without it only the in-game recording is taken).
1020
# Recording: ~/nfs_sessions/<date>[_hd] Analysis: python3 tools/session_report.py <dir>
1121
set -u
1222
ROOT="$(cd "$(dirname "$0")/.." && pwd)"
13-
HD=0
14-
for a in "$@"; do case "$a" in hd) HD=1 ;; *) echo "unknown: $a"; exit 1 ;; esac; done
23+
HD=0; ALL=0
24+
for a in "$@"; do case "$a" in hd) HD=1 ;; all) ALL=1 ;; *) echo "unknown: $a"; exit 1 ;; esac; done
1525
# the recording directory is tagged with the version: always clear which version was played
1626
VERSION="$(tr -cd '0-9' < "$ROOT/VERSION" 2>/dev/null)"; VERSION="${VERSION:-0}"
1727
SUF="_v$VERSION"; ENG=original
1828
[ $HD = 1 ] && { SUF="${SUF}_hd"; ENG=hd; }
1929
# NFSU2.app holds both engines (launcher picks one); an older separate "NFSU2 HD.app"
2030
# is used only when NFSU2.app has no HD engine.
21-
pick(){ for d in "$ROOT/out/personal" "$ROOT/out"; do [ -d "$d/$1" ] && { echo "$d/$1"; return; }; done; }
31+
# the bundle with the NEWEST engine (an old out/personal copy must not win over a fresh ./pack.sh)
32+
pick(){ local best="" d
33+
for d in "$ROOT/out/personal" "$ROOT/out"; do
34+
[ -d "$d/$1" ] || continue
35+
if [ -z "$best" ] || [ "$d/$1/Contents/MacOS/nfsu2-engine" -nt "$best/Contents/MacOS/nfsu2-engine" ]; then best="$d/$1"; fi
36+
done; echo "$best"; }
2237
APP="$(pick NFSU2.app)"
2338
if [ $HD = 1 ] && { [ -z "$APP" ] || [ ! -x "$APP/Contents/MacOS/nfsu2-engine-hd" ]; }; then
2439
APP="$(pick "NFSU2 HD.app")"
@@ -51,8 +66,21 @@ echo "starting the game: play normally (~5 min), quit the game when done."
5166
{ date; pmset -g batt; pmset -g | grep -i lowpowermode; } > "$DIR/battery_start.txt" 2>&1
5267
# DLINK=2: writes the real display refresh rate to the game's log every 5 s
5368
# NFSU2_SKIP_LAUNCHER: straight into the game, no launcher window
69+
EXTRA=()
70+
if [ "${SESSION_LIGHT:-0}" != 1 ]; then
71+
for kv in GAMELOG=1 TIMELOG=1 THREADLOG=1 FILEOPLOG=1 GILLOG=20 SNDSTAT=1 SNDGAP=1 \
72+
"SNDCSV=$DIR/sound.csv" "SNDDUMP=$DIR/sound_out.raw" \
73+
PASSPROF=120 "PASSPROF_CSV=$DIR/passprof.csv" GPUWIN=1,2000000000 MATLOG=1 TEXUPSAY=1; do
74+
EXTRA+=(--env "$kv"); done
75+
fi
76+
if [ $ALL = 1 ]; then
77+
for kv in TINT=none CONSOLEGAMMA=1 EDGEAA=1 SHARPEN=50 \
78+
NFSU2_REFLECT_SKY=1 NFSU2_REFLECT_LIGHTS=1 NFSU2_REFLECT_DETAIL=1; do
79+
EXTRA+=(--env "$kv"); done
80+
fi
81+
printf '%s\n' ${EXTRA[@]+"${EXTRA[@]}"} | grep -v '^--env$' > "$DIR/session_env.txt"
5482
open -W -n "$APP" --env NFSU2_SKIP_LAUNCHER=1 --env NFSU2_ENGINE=$ENG \
55-
--env PERFLOG="$DIR" --env DLINK=2 --stderr "$DIR/game.log"
83+
--env PERFLOG="$DIR" --env DLINK=2 ${EXTRA[@]+"${EXTRA[@]}"} --stderr "$DIR/game.log"
5684
{ date; pmset -g batt; pmset -g | grep -i lowpowermode; } > "$DIR/battery_end.txt" 2>&1
5785
LG=nfsu2; [ $HD = 1 ] && LG="$LG-hd"
5886
cp "$HOME/Library/Logs/NFSU2/$LG.log" "$DIR/game_full.log" 2>/dev/null

0 commit comments

Comments
 (0)