From a510083b4976ca5faafece15e0bde9f29c65e036 Mon Sep 17 00:00:00 2001 From: Mootjuh Date: Fri, 9 Oct 2026 06:14:35 +0200 Subject: [PATCH] Add a profiling build: CPU recordings for Perfetto and a report tool --- .github/workflows/build.yml | 2 +- README.md | 38 + configure.py | 13 +- port/linux/README.md | 2 + port/linux/game/network_distributed.c | 64 +- port/linux/game/network_objects.c | 18 +- port/linux/game/profile_console.c | 304 +++++ port/linux/game/profile_console.h | 25 + port/linux/include/profile_console_gametype.h | 30 + port/linux/include/profile_trace.h | 144 +++ port/linux/src/p2p.c | 60 + port/linux/src/port_config.c | 15 + port/linux/src/profile_json.c | 522 ++++++++ port/linux/src/profile_part.h | 97 ++ port/linux/src/profile_trace.c | 1006 ++++++++++++++++ source/cseries/profile.c | 113 ++ source/cseries/profile_sections.h | 31 + source/game/game.c | 71 +- source/game/game_time.c | 12 +- source/hs/hs.c | 9 + source/main/console.c | 7 + source/main/main.c | 51 +- tools/android_build.py | 4 +- tools/linux_build.py | 23 +- tools/net_report.py | 306 +++++ tools/profile_check.c | 1059 +++++++++++++++++ tools/profile_fixture.py | 66 + tools/profile_fixture.summary.txt | 35 + tools/test_profile.py | 569 +++++++++ tools/windows_build.py | 6 +- 30 files changed, 4640 insertions(+), 62 deletions(-) create mode 100644 port/linux/game/profile_console.c create mode 100644 port/linux/game/profile_console.h create mode 100644 port/linux/include/profile_console_gametype.h create mode 100644 port/linux/include/profile_trace.h create mode 100644 port/linux/src/profile_json.c create mode 100644 port/linux/src/profile_part.h create mode 100644 port/linux/src/profile_trace.c create mode 100644 source/cseries/profile_sections.h create mode 100644 tools/net_report.py create mode 100644 tools/profile_check.c create mode 100644 tools/profile_fixture.py create mode 100644 tools/profile_fixture.summary.txt create mode 100644 tools/test_profile.py diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 7e092a14..07b4ffcf 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -68,7 +68,7 @@ jobs: - name: Test run: | - python -m pytest -q tools/test_linux_port.py tools/harness + python -m pytest -q tools/test_linux_port.py tools/harness tools/test_profile.py python tools/test_light_storage.py - name: Compile cache diff --git a/README.md b/README.md index 2d9943fb..0bd435bb 100644 --- a/README.md +++ b/README.md @@ -114,6 +114,7 @@ Give these options to `configure.py`: | `--lto=thin`, `--lto=off` | Less link-time optimization. The link is faster. | | `--pgo=off` | No profile-guided optimization. | | `--pgo=train` | Records a new optimization profile. Refer to "Optimization profiles". | +| `--profile` | A profiling build. It records CPU times. Refer to "Profiling builds". | Without `--portable`, the Linux and Windows builds use all the instructions of the processor that builds them (`-march=native`). Such a build does not @@ -138,3 +139,40 @@ To record a new profile: The build then plays the main menu and the first minute of each campaign level. This procedure continues for approximately 15 minutes. The game data must be in `assets/`. + +### Profiling builds + +A profiling build records where the game spends its time. + +1. Enter `python configure.py --profile`, then build as usual. +2. Start a recording. Enter `profile_record` in the console (or the telnet + console), or set `debug.profile_record = true` in `config.toml`. To + record each game of a session, also set + `debug.profile_record_when = "game"`. +3. Stop the recording. Enter `profile_stop`, load another map, or quit. + +The game writes numbered `.part.json` files under `profiles/` in its data root +and logs their paths. Parts are retained after the recording stops. Logs go to +standard error; a Windows release build without standard error writes them to +`halo.log` next to `halo.exe`. + +`tools/net_report.py` is a helper for developers. Enter +`python tools/net_report.py ` to read a recording +as tables. The command also writes `.summary.txt`, a short text +file. + +| Command | Result | +| --- | --- | +| `profile_record [seconds]` | Starts a recording. With a number of seconds, the recording stops after that time. | +| `profile_stop` | Stops the recording. | + +`debug.profile_memory` sets the memory of a recording in MB (default 256, +from 4 to 1024). A recording has no length limit: +the game writes a part each time the memory is full. Refer to "Settings" in +[port/linux/README.md](port/linux/README.md). + +On Android, the files are in `/sdcard/Android/data/com.halo.decomp/files/profiles/`. +Enter `adb pull` to copy the recording parts to a computer. + +A profiling build plays with normal builds. It does not use +`--pgo=train`. diff --git a/configure.py b/configure.py index 3bff193b..3e5d042c 100644 --- a/configure.py +++ b/configure.py @@ -12,7 +12,7 @@ from types import SimpleNamespace from tools import ninja_syntax from tools.android_build import android_configure_inputs, generate_android_build -from tools.linux_build import generate_linux_build, linux_configure_inputs +from tools.linux_build import check_profile_options, generate_linux_build, linux_configure_inputs from tools.windows_build import generate_windows_build, windows_configure_inputs # arguments @@ -33,6 +33,12 @@ parser.add_argument( action="store_true", help="release builds (Linux, Windows, Android): assertions are not checked", ) +parser.add_argument( + "--profile", + action="store_true", + help="profiling builds (Linux, Windows, Android): CPU scopes recorded on a " + "console command or launch setting (README, \"Profiling builds\"); not with --pgo=train", +) parser.add_argument( "--lto", choices=["full", "thin", "off"], @@ -74,6 +80,10 @@ parser.add_argument( help="clang with the arm64_32 target for the Android guest (default: clang)", ) args = parser.parse_args() +try: + check_profile_options(args.profile, args.pgo) +except ValueError as error: + parser.error(str(error)) # the settings the builds read sln = SimpleNamespace( @@ -81,6 +91,7 @@ sln = SimpleNamespace( linux_cc=args.linux_cc, compiler_launcher=args.compiler_launcher, port_release=args.release, + port_profile=args.profile, port_lto=args.lto, port_portable=args.portable, port_pgo=args.pgo, diff --git a/port/linux/README.md b/port/linux/README.md index adc6f996..4f98f3ef 100644 --- a/port/linux/README.md +++ b/port/linux/README.md @@ -287,6 +287,8 @@ the setting for one start of the game. It has priority over the file. | `debug.network_test`, `debug.network_test_start`, `debug.network_test_kill`, `debug.network_test_score`, `debug.network_test_shoot`, `debug.network_test_vehicle`, `debug.network_test_pickup`, `debug.network_test_pickup_weapon`, `debug.test_input` | off | `HALO_NETWORK_TEST`, `HALO_NETWORK_TEST_START`, `HALO_NETWORK_TEST_KILL`, `HALO_NETWORK_TEST_SCORE`, `HALO_NETWORK_TEST_SHOOT`, `HALO_NETWORK_TEST_VEHICLE`, `HALO_NETWORK_TEST_PICKUP`, `HALO_NETWORK_TEST_PICKUP_WEAPON`, `HALO_TEST_INPUT` | Automatic tests of system link (`game/network_test.c`). Refer to `NETCODE.md`. | | `debug.network_latency`, `debug.network_loss`, `debug.network_corrupt`, `debug.network_corrupt_stream`, `debug.network_corrupt_after` | `0` | `HALO_NETWORK_LATENCY`, `HALO_NETWORK_LOSS`, `HALO_NETWORK_CORRUPT`, `HALO_NETWORK_CORRUPT_STREAM`, `HALO_NETWORK_CORRUPT_AFTER` | The game holds all the data that it receives for this number of milliseconds, ignores this percentage of the datagrams, and damages this percentage of the datagrams it receives, and this percentage of its reads of streams, at random (bytes changed, cut short, stretched or replaced), from this many seconds after the start. Use the first two to test the netcode as on the internet, and the others to test that nothing another machine sends can crash the game (a damaged stream is closed, so a little goes a long way; a host's messages to its own client are damaged too, so start damaging once the game has started). | | `debug.telnet_console`, `debug.telnet_console_port` | `false`, `2323` | `HALO_TELNET_CONSOLE`, `HALO_TELNET_CONSOLE_PORT` | The game listens on 127.0.0.1, on this port, for a script console (connect with telnet). The console has no password, so only this computer can reach it. | +| `debug.profile_record`, `debug.profile_record_when`, `debug.profile_memory` | `false`, `"start"`, `256` | `HALO_PROFILE_RECORD`, `HALO_PROFILE_RECORD_WHEN`, `HALO_PROFILE_MEMORY` | Profiling builds only (`configure.py --profile`). Record without a command; `"start"` records from the first frame until the first map change, `"game"` records each game outside the main menu. Memory is 4–1024 MB. Numbered `profile__.part.json` files remain in `profiles/` after recording. Refer to "Profiling builds" in the main README. | + With Mesa drivers, the game sends its GL calls through the GL thread of Mesa. To stop this, set the environment variable `mesa_glthread=false`. diff --git a/port/linux/game/network_distributed.c b/port/linux/game/network_distributed.c index 24cc1048..5bd843f4 100644 --- a/port/linux/game/network_distributed.c +++ b/port/linux/game/network_distributed.c @@ -72,6 +72,7 @@ machine (their datum identifiers need not be). #include "units/bipeds.h" #include "network_coop.h" #include "network_distributed.h" +#include "cseries/profile_sections.h" #include #include @@ -457,6 +458,28 @@ struct distributed_packer static long distributed_last_sent_time = NONE; +/* the tick's steps, timed in the profiling build */ +PROFILE_SECTION(distributed_tick_apply_predictions_section, "network_distributed_tick.apply_predictions") +PROFILE_SECTION(distributed_tick_apply_vehicle_predictions_section, "network_distributed_tick.apply_vehicle_predictions") +PROFILE_SECTION(distributed_tick_objects_host_tick_section, "network_distributed_tick.objects_host_tick") +PROFILE_SECTION(distributed_tick_plan_players_section, "network_distributed_tick.plan_players") +PROFILE_SECTION(distributed_tick_damage_host_tick_section, "network_distributed_tick.damage_host_tick") +PROFILE_SECTION(distributed_tick_send_statistics_section, "network_distributed_tick.send_statistics") +PROFILE_SECTION(distributed_tick_send_pings_section, "network_distributed_tick.send_pings") +PROFILE_SECTION(distributed_tick_send_structure_bsp_section, "network_distributed_tick.send_structure_bsp") +PROFILE_SECTION(distributed_tick_send_players_section, "network_distributed_tick.send_players") +PROFILE_SECTION(distributed_tick_actors_host_tick_section, "network_distributed_tick.actors_host_tick") +PROFILE_SECTION(distributed_tick_coop_host_tick_section, "network_distributed_tick.coop_host_tick") +PROFILE_SECTION(distributed_tick_send_pickups_section, "network_distributed_tick.send_pickups") +PROFILE_SECTION(distributed_tick_send_game_state_section, "network_distributed_tick.send_game_state") +PROFILE_SECTION(distributed_tick_note_own_positions_section, "network_distributed_tick.note_own_positions") +PROFILE_SECTION(distributed_tick_send_inputs_section, "network_distributed_tick.send_inputs") +PROFILE_SECTION(distributed_tick_send_predictions_section, "network_distributed_tick.send_predictions") +PROFILE_SECTION(distributed_tick_objects_client_tick_section, "network_distributed_tick.objects_client_tick") +PROFILE_SECTION(distributed_tick_damage_client_tick_section, "network_distributed_tick.damage_client_tick") +PROFILE_SECTION(distributed_tick_coop_client_tick_section, "network_distributed_tick.coop_client_tick") +PROFILE_SECTION(distributed_tick_batches_flush_section, "network_distributed_tick.batches_flush") + /* how each player last died, by absolute index: the host's own, which it sends its clients, and a client's copy of the host's */ static struct distributed_death @@ -3331,40 +3354,41 @@ void network_distributed_tick( decided first: the damage goes where the players it hurt do), and a kill's statistics before the kill, so that a client announcing it counts it (a double kill, a killing spree) */ - distributed_apply_predictions(); - network_objects_apply_vehicle_predictions(); - network_objects_host_tick(); - distributed_host_plan_players(); - network_damage_host_tick(); + profile_scope(distributed_tick_apply_predictions_section, distributed_apply_predictions();) + profile_scope(distributed_tick_apply_vehicle_predictions_section, network_objects_apply_vehicle_predictions();) + profile_scope(distributed_tick_objects_host_tick_section, network_objects_host_tick();) + profile_scope(distributed_tick_plan_players_section, distributed_host_plan_players();) + profile_scope(distributed_tick_damage_host_tick_section, network_damage_host_tick();) if (distributed_statistics_due || game_time_get() % STATISTICS_INTERVAL_TICKS == 0) - distributed_send_statistics(game_time_get() % STATISTICS_REFRESH_TICKS == 0); + profile_scope(distributed_tick_send_statistics_section, + distributed_send_statistics(game_time_get() % STATISTICS_REFRESH_TICKS == 0);) distributed_statistics_due = FALSE; if (game_time_get() % PING_INTERVAL_TICKS == 0) - distributed_send_pings(); + profile_scope(distributed_tick_send_pings_section, distributed_send_pings();) /* (before the players, so clients load a new BSP before they hear where the host moved everyone into it) */ if (network_coop_active() && (global_structure_bsp_index_get() != distributed_sent_structure_bsp_index || game_time_get() % STRUCTURE_BSP_INTERVAL_TICKS == 0)) { - distributed_send_structure_bsp(); + profile_scope(distributed_tick_send_structure_bsp_section, distributed_send_structure_bsp();) } - distributed_host_send_players(); - network_actors_host_tick(); - network_coop_host_tick(); - distributed_send_pickups(); + profile_scope(distributed_tick_send_players_section, distributed_host_send_players();) + profile_scope(distributed_tick_actors_host_tick_section, network_actors_host_tick();) + profile_scope(distributed_tick_coop_host_tick_section, network_coop_host_tick();) + profile_scope(distributed_tick_send_pickups_section, distributed_send_pickups();) if (game_time_get() % GAME_STATE_INTERVAL_TICKS == 0) - distributed_send_game_state(NONE); + profile_scope(distributed_tick_send_game_state_section, distributed_send_game_state(NONE);) } else if (connection == _game_connection_network_client) { - distributed_note_own_positions(); - distributed_client_send_inputs(); - distributed_client_send_predictions(); - network_objects_client_tick(); - network_damage_client_tick(); - network_coop_client_tick(); + profile_scope(distributed_tick_note_own_positions_section, distributed_note_own_positions();) + profile_scope(distributed_tick_send_inputs_section, distributed_client_send_inputs();) + profile_scope(distributed_tick_send_predictions_section, distributed_client_send_predictions();) + profile_scope(distributed_tick_objects_client_tick_section, network_objects_client_tick();) + profile_scope(distributed_tick_damage_client_tick_section, network_damage_client_tick();) + profile_scope(distributed_tick_coop_client_tick_section, network_coop_client_tick();) } - distributed_batches_flush(); + profile_scope(distributed_tick_batches_flush_section, distributed_batches_flush();) distributed_machines.in_tick = FALSE; distributed_machines.valid = FALSE; } diff --git a/port/linux/game/network_objects.c b/port/linux/game/network_objects.c index 8ee2020e..5138a877 100644 --- a/port/linux/game/network_objects.c +++ b/port/linux/game/network_objects.c @@ -64,6 +64,7 @@ same datum index (identifier and all), so that any message can name one: #include "cutscene/cinematics.h" #include "network_coop.h" #include "network_distributed.h" +#include "cseries/profile_sections.h" #include @@ -1976,15 +1977,22 @@ void network_objects_apply_vehicle_predictions( } } +/* the host tick's steps, timed in the profiling build */ +PROFILE_SECTION(objects_host_tick_update_objects_section, "network_objects_host_tick.update_objects") +PROFILE_SECTION(objects_host_tick_find_viewers_section, "network_objects_host_tick.find_viewers") +PROFILE_SECTION(objects_host_tick_send_states_section, "network_objects_host_tick.send_states") +PROFILE_SECTION(objects_host_tick_send_inventories_section, "network_objects_host_tick.send_inventories") +PROFILE_SECTION(objects_host_tick_send_damage_animations_section, "network_objects_host_tick.send_damage_animations") + void network_objects_host_tick( void) { - distributed_host_update_objects(); - distributed_host_find_viewers(); - distributed_host_send_states(); + profile_scope(objects_host_tick_update_objects_section, distributed_host_update_objects();) + profile_scope(objects_host_tick_find_viewers_section, distributed_host_find_viewers();) + profile_scope(objects_host_tick_send_states_section, distributed_host_send_states();) if (game_time_get() % INVENTORY_INTERVAL_TICKS == 0) - distributed_host_send_inventories(); - distributed_host_send_damage_animations(); + profile_scope(objects_host_tick_send_inventories_section, distributed_host_send_inventories();) + profile_scope(objects_host_tick_send_damage_animations_section, distributed_host_send_damage_animations();) } /* ---------- a client */ diff --git a/port/linux/game/profile_console.c b/port/linux/game/profile_console.c new file mode 100644 index 00000000..7e0057c0 --- /dev/null +++ b/port/linux/game/profile_console.c @@ -0,0 +1,304 @@ +/* +PROFILE_CONSOLE.C + +Connect profiling commands and launch settings to game recordings. +*/ + +#ifdef HALO_PROFILE + +#include "cseries.h" +#include "game/game.h" +#include "game/game_engine.h" +#include "main/console.h" +#include "networking/network_game_globals.h" +#include "network_distributed.h" +#include "profile_console.h" +#include "profile_console_gametype.h" +#include "profile_trace.h" + +#include +#include +#include + +/* the platform layer's (platform.h, port_config.h), and main.c's */ +void platform_log(const char *format, ...); +const char *platform_data_root(void); +int posix_make_directory(const char *path); +void *posix_directory_open(const char *path); +void posix_directory_close(void *directory); +void p2p_profile_lock(void); +void p2p_profile_unlock(void); +int config_boolean(const char *name); +long config_integer(const char *name); +const char *config_string(const char *name); +boolean main_menu_is_loaded(void); + + +/* ---------- globals */ + +static boolean profile_console_installed; + +static void profile_console_map_component(const char *map, char *name, int size) +{ + const char *component = map; + const char *cursor; + int used = 0; + + for (cursor = map; *cursor; cursor++) + if (*cursor == '/' || *cursor == '\\') + component = cursor + 1; + for (cursor = component; *cursor && used + 1 < size; cursor++) + { + unsigned char character = (unsigned char)*cursor; + if (character >= 'A' && character <= 'Z') + character = (unsigned char)(character + ('a' - 'A')); + name[used++] = (character >= 'a' && character <= 'z') || (character >= '0' && character <= '9') || + character == '_' || character == '-' ? (char)character : '-'; + } + name[used] = 0; +} + +static const char *profile_console_gametype(void) +{ + long engine; + + if (!game_in_progress() || main_menu_is_loaded() || game_connection() == _game_connection_film_playback) + return "none"; + if (!game_engine_running()) + return profile_console_engine_gametype(FALSE, 0); + engine = game_engine_get_variant()->game_engine_index; + return profile_console_engine_gametype(TRUE, engine); +} + +/* the map the header names: the one loading takes its place only after the +frame boundary that stops a recording on it (profile_console_frame) */ +static char profile_console_map[64]; +static char profile_console_next_map[64]; + +/* ---------- private code */ + +static void profile_console_log( + const char *text) +{ + platform_log("profile: %s", text); +} + +static void profile_console_notify( + const char *text) +{ + console_printf(FALSE, "%s", text); +} + +static int profile_console_ready( + void) +{ + return game_in_progress() && !main_menu_is_loaded(); +} + +static void profile_console_session( + struct profile_trace_session *session) +{ + short player_index; + const char *scenario = profile_console_scenario_map(profile_console_next_map, profile_console_map); + void *folder; + + csmemset(session, 0, sizeof(*session)); + snprintf(session->folder, sizeof(session->folder), "%s/profiles", platform_data_root()); + posix_make_directory(session->folder); + /* (a folder that can't be made must not lose the recording: the parts go + to the data root itself then) */ + folder = posix_directory_open(session->folder); + if (folder) + posix_directory_close(folder); + else + strncpy(session->folder, platform_data_root(), sizeof(session->folder) - 1); +#ifdef HALO_RELEASE + strcpy(session->build, "release profile"); +#else + strcpy(session->build, "debug profile"); +#endif + session->own_machine = -1; + switch (game_connection()) + { + case _game_connection_network_server: + strcpy(session->role, "host"); + break; + case _game_connection_network_client: + strcpy(session->role, "client"); + session->own_machine = network_game_client_get_local_machine_index(); + break; + default: + strcpy(session->role, "local"); + break; + } + strncpy(session->map, scenario, sizeof(session->map) - 1); + profile_console_map_component(scenario, session->map_name, sizeof(session->map_name)); + strncpy(session->gametype, profile_console_gametype(), sizeof(session->gametype) - 1); + for (player_index = 0; player_index < MAXIMUM_TRACKED_PLAYERS; player_index++) + { + if (distributed_player(player_index)) + session->players++; + } + session->players_most = session->players; +} + +/* (once a second on the game thread: unlike the start-time description it +makes and opens no folder, which would land in the measured frame) */ +static void profile_console_sample_session( + struct profile_trace_session *session) +{ + short player_index; + const char *scenario = profile_console_scenario_map(profile_console_next_map, profile_console_map); + + if (!session->map_name[0] && scenario[0]) + { + strncpy(session->map, scenario, sizeof(session->map) - 1); + profile_console_map_component(scenario, session->map_name, sizeof(session->map_name)); + strncpy(session->gametype, profile_console_gametype(), sizeof(session->gametype) - 1); + } + for (player_index = 0; player_index < MAXIMUM_TRACKED_PLAYERS; player_index++) + if (distributed_player(player_index)) + session->players++; +} + +/* the recording's seams. Not left to the first frame: init.txt's +profile_record is handled before it, and the recording's name (folder and +role) is chosen from the session when it is requested */ +static void profile_console_install( + void) +{ + if (profile_console_installed) + return; + profile_console_installed = TRUE; + profile_trace_set_log(profile_console_log); + profile_trace_set_notify(profile_console_notify); + profile_trace_set_ready(profile_console_ready); + profile_trace_set_session(profile_console_session); + profile_trace_set_session_sampler(profile_console_sample_session); + profile_trace_set_track_lock(p2p_profile_lock, p2p_profile_unlock); + /* (the window's close, debug.exit_after and XLaunchNewImage end the + process with exit(), which main_exit never sees) */ + atexit(profile_trace_shutdown); +} + +/* what follows the command word an expression starts with (past spaces and +an opening parenthesis, as the console and init.txt give it), else NULL */ +static char const *profile_console_word( + char const *expression, + char const *word) +{ + long length = (long)strlen(word); + long index; + + while (*expression == ' ' || *expression == '\t' || *expression == '(') + expression++; + for (index = 0; index < length; index++) + { + char character = expression[index] >= 'A' && expression[index] <= 'Z' ? expression[index] - 'A' + 'a' : expression[index]; + + if (character != word[index]) + return NULL; + } + expression += length; + if (*expression && *expression != ' ' && *expression != '\t' && *expression != ')') + return NULL; + while (*expression == ' ' || *expression == '\t') + expression++; + return expression; +} + +/* ---------- public code */ + +void profile_console_launch( + void) +{ + char const *when = config_string("debug.profile_record_when"); + + strcpy(profile_console_map, profile_console_next_map); + profile_console_install(); + profile_trace_thread_register(_profile_track_game); + if (strcmp(when, "start") != 0 && strcmp(when, "game") != 0) + platform_log("profile: debug.profile_record_when is \"%s\": \"start\" taken", when); + if (config_boolean("debug.profile_record")) + { + profile_trace_request_start(0.0, strcmp(when, "game") == 0 ? _profile_trace_when_game : _profile_trace_when_now, + config_integer("debug.profile_memory")); + } +} + +void profile_console_frame( + void) +{ + + strcpy(profile_console_map, profile_console_next_map); +} + +void profile_console_map_loaded( + char const *map_name) +{ + strncpy(profile_console_next_map, map_name ? map_name : "", sizeof(profile_console_next_map) - 1); + profile_trace_map_loaded(); +} + +/* Parse these before the script compiler: compiled map scripts index the +script function table, so profiling commands must not add entries to it. */ +boolean profile_console_command( + char const *expression) +{ + struct profile_trace_status status; + char const *rest; + + profile_console_install(); + if ((rest = profile_console_word(expression, "profile_record")) != NULL) + { + char *end; + double seconds = strtod(rest, &end); + + if (end == rest) + seconds = 0.0; + if ((*rest && end == rest) || seconds < 0.0 || + (*end && *end != ' ' && *end != '\t' && *end != ')')) + { + console_printf(FALSE, "profile: profile_record takes a number of seconds, 0 or more"); + return TRUE; + } + switch (profile_trace_request_start(seconds, _profile_trace_when_now, config_integer("debug.profile_memory"))) + { + case _profile_trace_answer_armed: + profile_trace_status(&status); + if (seconds > 0.0) + console_printf(FALSE, "profile: recording %s, %g s", status.name, seconds); + else + console_printf(FALSE, "profile: recording %s, until profile_stop", status.name); + break; + case _profile_trace_answer_still_writing: + profile_trace_status(&status); + console_printf(FALSE, "profile: still writing %s", status.name); + break; + default: + console_printf(FALSE, "profile: already recording"); + break; + } + return TRUE; + } + if (profile_console_word(expression, "profile_stop")) + { + profile_trace_status(&status); + switch (profile_trace_request_stop()) + { + case _profile_trace_answer_stopping: + console_printf(FALSE, "profile: writing %s, %ld parts", status.name, status.part); + break; + case _profile_trace_answer_disarmed: + console_printf(FALSE, "profile: not waiting for a game any more"); + break; + default: + console_printf(FALSE, "profile: not recording"); + break; + } + return TRUE; + } + return FALSE; +} + +#endif diff --git a/port/linux/game/profile_console.h b/port/linux/game/profile_console.h new file mode 100644 index 00000000..8502bc7f --- /dev/null +++ b/port/linux/game/profile_console.h @@ -0,0 +1,25 @@ +/* +PROFILE_CONSOLE.H + +Expose the game recording console hooks. +*/ + +#ifndef __PROFILE_CONSOLE_H +#define __PROFILE_CONSOLE_H +#pragma once + +#ifdef HALO_PROFILE + +/* profile_record [seconds], profile_stop: TRUE +when the expression was one of them (hs.c, before the script compiler) */ +boolean profile_console_command(char const *expression); +/* the first frame: the recording's seams, and the launch settings */ +void profile_console_launch(void); +/* each frame, right after the frame boundary */ +void profile_console_frame(void); +/* a map starts loading (game_load) */ +void profile_console_map_loaded(char const *map_name); + +#endif + +#endif diff --git a/port/linux/include/profile_console_gametype.h b/port/linux/include/profile_console_gametype.h new file mode 100644 index 00000000..259cb397 --- /dev/null +++ b/port/linux/include/profile_console_gametype.h @@ -0,0 +1,30 @@ +/* +PROFILE_CONSOLE_GAMETYPE.H + +Name the current scenario and running game engine for recordings. +*/ + +#ifndef __PROFILE_CONSOLE_GAMETYPE_H +#define __PROFILE_CONSOLE_GAMETYPE_H + +static inline const char *profile_console_scenario_map(const char *pending, const char *current) +{ + return pending && pending[0] ? pending : current; +} + +/* (engine indices none, ctf, slayer, oddball, king, race; the check program +cannot include game_engine.h. The variant outlives the engine into campaign +and co-op, so it is read only while an engine runs) */ +static inline const char *profile_console_engine_gametype(int running, long engine) +{ + static const char *const names[] = { "none", "ctf", "slayer", "oddball", "king", "race" }; + if (!running) + return "campaign"; + if (engine == 0) + return "none"; + if (engine >= 1 && engine <= 5) + return names[engine]; + return "none"; +} + +#endif diff --git a/port/linux/include/profile_trace.h b/port/linux/include/profile_trace.h new file mode 100644 index 00000000..324a95d2 --- /dev/null +++ b/port/linux/include/profile_trace.h @@ -0,0 +1,144 @@ +/* +PROFILE_TRACE.H + +Expose bounded CPU trace recording and session controls. +*/ + +#ifndef __PROFILE_TRACE_H +#define __PROFILE_TRACE_H + +#ifdef HALO_PROFILE + +/* included by C89 game units: keep declarations compatible with them. */ + +/* ---------- constants */ + +enum +{ + _profile_track_game = 0, + _profile_track_p2p, + NUMBER_OF_PROFILE_TRACKS, + + MAXIMUM_PROFILE_TRACE_NAMES = 512, + MAXIMUM_PROFILE_TRACE_DEPTH = 64, + MAXIMUM_PROFILE_TRACE_AGGREGATES = 32, + /* debug.profile_memory: both arenas together, megabytes */ + DEFAULT_PROFILE_TRACE_MEMORY = 256, + MINIMUM_PROFILE_TRACE_MEMORY = 4, + MAXIMUM_PROFILE_TRACE_MEMORY = 1024, +}; + +enum profile_trace_state +{ + _profile_trace_idle = 0, + _profile_trace_armed, + _profile_trace_recording, + _profile_trace_finishing, +}; + +/* when an armed recording starts: at the next frame, or once a game that is +not the main menu is in progress (debug.profile_record_when = "game") */ +enum profile_trace_when +{ + _profile_trace_when_now = 0, + _profile_trace_when_game, +}; + +enum profile_trace_stop_reason +{ + _profile_trace_stop_none = 0, + _profile_trace_stop_command, + _profile_trace_stop_seconds, + _profile_trace_stop_map_load, + _profile_trace_stop_exit, +}; + +enum profile_trace_answer +{ + _profile_trace_answer_armed = 0, + _profile_trace_answer_already_recording, + _profile_trace_answer_still_writing, + _profile_trace_answer_stopping, + _profile_trace_answer_disarmed, + _profile_trace_answer_not_recording, +}; + +/* ---------- structures */ + +/* (the recording's identity at start; players_most grows while it runs) */ +struct profile_trace_session +{ + char folder[260]; + char platform[16]; + char build[48]; + /* host, client or local */ + char role[8]; + /* a client's own machine index, -1 otherwise */ + long own_machine; + char map[64]; + char map_name[64]; + char gametype[16]; + long players; + long players_most; +}; + +struct profile_trace_status +{ + int state; + char name[64]; + long part; +}; + +/* ---------- prototypes/PROFILE_TRACE.C */ + +/* the seams: set once at start-up by the game (profile_console.c), and by +tools/profile_check.c with fakes */ +void profile_trace_set_clock(unsigned long long (*now_ns)(void)); +void profile_trace_set_track_lock(void (*lock)(void), void (*unlock)(void)); +void profile_trace_set_allocator(void *(*allocate)(unsigned long size), void (*release)(void *block)); +void profile_trace_set_log(void (*log)(const char *text)); +void profile_trace_set_notify(void (*notify)(const char *text)); +/* starts the writer of a new recording (profile_json_writer_start): 0 when +it cannot */ +void profile_trace_set_writer(int (*start)(void)); +/* whether a game that is not the main menu is in progress */ +void profile_trace_set_ready(int (*ready)(void)); +void profile_trace_set_session(void (*describe)(struct profile_trace_session *session)); +void profile_trace_set_session_sampler(void (*sample)(struct profile_trace_session *session)); + +/* which track the calling thread records on */ +void profile_trace_thread_register(int track); + +/* a name's id (the same name, the same id, for the whole run); an +aggregate name's scopes are summed per frame rather than recorded */ +int profile_trace_name(const char *name); +void profile_trace_name_aggregate(const char *name); + +void profile_trace_begin(int name); +void profile_trace_end(int name); + +/* the game thread, with no scope open: where a recording starts, is cut +and stops */ +void profile_trace_frame_boundary(void); +/* the game thread, at each game tick's start */ +void profile_trace_tick(void); + +/* the console's requests (the game thread), applied at the next frame +boundary; seconds 0 records until stopped */ +int profile_trace_request_start(double seconds, int when, long memory_megabytes); +int profile_trace_request_stop(void); +/* a map starts loading: a recording stops, but for the first load after +launch (the main menu, or init.txt's map) */ +void profile_trace_map_loaded(void); +/* the process ends: stops a recording, cuts its last part and waits for +the writer (main_exit, and atexit for the other ways out) */ +void profile_trace_shutdown(void); + +/* whether the tracks record now: changed under the track lock, so a p2p +pass sees one value */ +int profile_trace_recording(void); +void profile_trace_status(struct profile_trace_status *status); + +#endif + +#endif diff --git a/port/linux/src/p2p.c b/port/linux/src/p2p.c index 73f18275..d2ed6d6d 100644 --- a/port/linux/src/p2p.c +++ b/port/linux/src/p2p.c @@ -58,6 +58,9 @@ only look up and create stand-ins. #include "port_config.h" #include "p2p_internal.h" #include "ikcp.h" +#ifdef HALO_PROFILE +#include "profile_trace.h" +#endif #include #include @@ -276,6 +279,32 @@ struct stun_server pthread_mutex_t p2p_lock = PTHREAD_MUTEX_INITIALIZER; +#ifdef HALO_PROFILE +/* the p2p thread's own track of the profiling build's recording +(profile_trace.c): profile.c's sections are the game thread's alone */ +static struct +{ + int pass; + int tunnel_receive; + int kcp_update; + int streams; +} p2p_profile_names; + +/* the recording's track lock: the game thread flips the recording and its +arenas under it, and this thread records under it, so each record lands in +one arena; a pass that drops the lock (DNS, key exchange) can straddle a +cut, and profile_trace_end drops that scope */ +void p2p_profile_lock(void) +{ + pthread_mutex_lock(&p2p_lock); +} + +void p2p_profile_unlock(void) +{ + pthread_mutex_unlock(&p2p_lock); +} +#endif + static struct { int running; @@ -2824,6 +2853,13 @@ static void *p2p_thread(void *unused) static int read_owners[MAXIMUM_SOCKETS], write_owners[MAXIMUM_SOCKETS]; (void)unused; +#ifdef HALO_PROFILE + profile_trace_thread_register(_profile_track_p2p); + p2p_profile_names.pass = profile_trace_name("p2p.pass"); + p2p_profile_names.tunnel_receive = profile_trace_name("p2p.tunnel_receive"); + p2p_profile_names.kcp_update = profile_trace_name("p2p.kcp_update"); + p2p_profile_names.streams = profile_trace_name("p2p.streams"); +#endif pthread_mutex_lock(&p2p_lock); #ifndef HALO_ANDROID /* (here: it may wait for a program) */ @@ -2903,6 +2939,9 @@ static void *p2p_thread(void *unused) read_count = write_count = 0; } pthread_mutex_lock(&p2p_lock); +#ifdef HALO_PROFILE + profile_trace_begin(p2p_profile_names.pass); +#endif /* what is ready (the lists now hold only ready sockets, in the order asked, so each one's owner is found going along both); a socket @@ -2921,7 +2960,13 @@ static void *p2p_thread(void *unused) switch (owner & 255) { case _owner_tunnel: +#ifdef HALO_PROFILE + profile_trace_begin(p2p_profile_names.tunnel_receive); +#endif tunnel_readable(); +#ifdef HALO_PROFILE + profile_trace_end(p2p_profile_names.tunnel_receive); +#endif break; case _owner_handoff: if (socket == p2p.handoff_socket) @@ -2941,6 +2986,9 @@ static void *p2p_thread(void *unused) break; } } +#ifdef HALO_PROFILE + profile_trace_begin(p2p_profile_names.streams); +#endif for (index = 0, asked = 0; index < write_count; index++) { int socket = write[index]; @@ -2965,13 +3013,22 @@ static void *p2p_thread(void *unused) if (stream->used && stream->state == _stream_connecting && elapsed(stream->created_time, 5000)) stream_local_closed(stream); } +#ifdef HALO_PROFILE + profile_trace_end(p2p_profile_names.streams); +#endif p2p_signal_update(read, read_count, write, write_count); +#ifdef HALO_PROFILE + profile_trace_begin(p2p_profile_names.kcp_update); +#endif for (index = 0; index < MAXIMUM_STREAMS; index++) { if (p2p.streams[index].used) stream_update(&p2p.streams[index]); } +#ifdef HALO_PROFILE + profile_trace_end(p2p_profile_names.kcp_update); +#endif update_peers(); expire_proxies(); stun_update(); @@ -2999,6 +3056,9 @@ static void *p2p_thread(void *unused) p2p_discord_update(); #ifdef HALO_ANDROID poll_invite_file(); +#endif +#ifdef HALO_PROFILE + profile_trace_end(p2p_profile_names.pass); #endif } return NULL; diff --git a/port/linux/src/port_config.c b/port/linux/src/port_config.c index 2d0d5f58..82695219 100644 --- a/port/linux/src/port_config.c +++ b/port/linux/src/port_config.c @@ -451,6 +451,21 @@ static const struct config_setting config_settings[] = { "debug.sample_seconds", _config_real, "0.0", "HALO_SAMPLE", _environment_value, _platform_android, "Log where every game thread is this often, in seconds (read by the\n" "app, port/android/host/host_debug.c); 0 never." }, +#ifdef HALO_PROFILE + { "debug.profile_record", _config_boolean, "false", "HALO_PROFILE_RECORD", _environment_value, _platform_all, + "Record a profile with no command (configure.py --profile builds): from\n" + "when profile_record_when says until profile_stop, a map change or the\n" + "end, into numbered part files in the data folder's profiles folder\n" + "(tools/net_report.py reads it)." }, + { "debug.profile_record_when", _config_string, "\"start\"", "HALO_PROFILE_RECORD_WHEN", _environment_value, + _platform_all, + "\"start\": from the first frame until the first map change; \"game\":\n" + "each game that is not the main menu, a recording each, until its map\n" + "goes." }, + { "debug.profile_memory", _config_integer, "256", "HALO_PROFILE_MEMORY", _environment_value, _platform_all, + "Megabytes a recording keeps in memory, 4 to 1024: two halves, each\n" + "written out as a part when it fills." }, +#endif }; #define NUMBER_OF_CONFIG_SETTINGS (sizeof(config_settings) / sizeof(config_settings[0])) diff --git a/port/linux/src/profile_json.c b/port/linux/src/profile_json.c new file mode 100644 index 00000000..5942eb38 --- /dev/null +++ b/port/linux/src/profile_json.c @@ -0,0 +1,522 @@ +/* +PROFILE_JSON.C + +Write recording parts on the writer thread. +*/ + +#ifdef HALO_PROFILE + +#include "profile_part.h" + +#include +#include +#include + +/* ---------- constants */ + +enum +{ + PROFILE_JSON_WORST_FRAMES = 10, + PROFILE_JSON_LONGEST_CHILDREN = 3, +}; + +/* ---------- structures */ + +/* where the next item of a list goes: a comma and a line before all but +the first */ +struct profile_json_list +{ + FILE *file; + int items; +}; + +struct profile_json_name_totals +{ + unsigned long long count; + unsigned long long total; + unsigned long long maximum; +}; + +/* ---------- globals */ + +static const char *profile_json_stop_reasons[] = { "", "command", "seconds", "map_load", "exit" }; + +/* ---------- private code */ + +static void profile_json_item( + struct profile_json_list *list) +{ + if (list->items++) + fputs(",\n", list->file); +} + +static void profile_json_escaped( + FILE *file, + const char *text) +{ + for (; text && *text; text++) + { + unsigned char character = (unsigned char)*text; + + if (character == '"' || character == '\\') + fprintf(file, "\\%c", character); + else if (character < 32 || character > 126) + fprintf(file, "\\u%04x", character); + else + fputc(character, file); + } +} + +static void profile_json_string( + FILE *file, + const char *text) +{ + fputc('"', file); + profile_json_escaped(file, text); + fputc('"', file); +} + +/* microseconds with three decimals, as the trace event format has them */ +static void profile_json_time( + FILE *file, + unsigned long long nanoseconds) +{ + fprintf(file, "%llu.%03llu", nanoseconds / 1000ULL, nanoseconds % 1000ULL); +} + +static int profile_json_compare_records( + const void *a, + const void *b) +{ + const struct profile_trace_record *first = a; + const struct profile_trace_record *second = b; + + if (first->start != second->start) + return first->start < second->start ? -1 : 1; + return (int)first->depth - (int)second->depth; +} + +static int profile_json_name_of( + const struct profile_part *part, + const char *text) +{ + int name; + + for (name = 0; name < part->name_count; name++) + { + if (strcmp(profile_trace_name_text(name), text) == 0) + return name; + } + return -1; +} + +static void profile_json_header( + const struct profile_part *part, + FILE *file) +{ + const struct profile_trace_session *session = &part->session; + + fputs("\"header\": {\"format\": 1, \"build\": ", file); + profile_json_string(file, session->build); + fputs(", \"platform\": ", file); + profile_json_string(file, session->platform); + fputs(", \"role\": ", file); + profile_json_string(file, session->role); + fprintf(file, ", \"own_machine\": %ld, \"map\": ", session->own_machine); + profile_json_string(file, session->map); + fputs(", \"map_name\": ", file); + profile_json_string(file, session->map_name); + fputs(", \"gametype\": ", file); + profile_json_string(file, session->gametype); + fprintf(file, ", \"players\": %ld, \"players_most\": %ld, \"start_utc\": ", session->players, + session->players_most); + profile_json_string(file, part->start_utc); + fputs(", \"recording\": ", file); + profile_json_string(file, part->name); + fprintf(file, ", \"part\": %ld, \"last_part\": %s" + ", \"first_frame\": %ld, \"frames\": %ld, \"first_tick\": %ld, \"ticks\": %ld", + part->number, part->last ? "true" : "false", + part->first_frame, part->frames, part->first_tick, part->ticks); + fprintf(file, ", \"start_s\": %.6f, \"duration_s\": %.6f, \"stop_reason\": ", + (double)part->start_ns / 1e9, (double)(part->end_ns - part->start_ns) / 1e9); + profile_json_string(file, profile_json_stop_reasons[part->stop_reason]); + fprintf(file, ", \"clock_read_ns\": %.1f, \"memory_used\": %lu, \"memory_limit\": %lu, \"writer_wait_ms\": %.3f" + ", \"foreign_scopes\": %lu, \"deep_scopes\": %lu, \"unbalanced_scopes\": %lu, \"dropped_scopes\": %lu}", + part->clock_read_ns, part->memory_used, part->memory_limit, part->writer_wait_ms, + part->foreign_scopes, part->deep_scopes, part->unbalanced_scopes, part->dropped_scopes); +} + +/* a worst frame's scopes: the open ones (one a depth, so no more than the +depth limit) and the three with the most time of their own so far */ +struct profile_json_ranking +{ + unsigned long scope[MAXIMUM_PROFILE_TRACE_DEPTH]; + unsigned long long children[MAXIMUM_PROFILE_TRACE_DEPTH]; + int open; + unsigned long longest[PROFILE_JSON_LONGEST_CHILDREN]; + unsigned int own[PROFILE_JSON_LONGEST_CHILDREN]; + int count; +}; + +/* the innermost open scope ends: its time less its children's is ranked, and +all of it is its parent's child time */ +static void profile_json_close( + struct profile_json_ranking *ranking, + const struct profile_trace_record *game) +{ + int open = --ranking->open; + unsigned long scope = ranking->scope[open]; + unsigned long long duration = game[scope].duration; + unsigned int own = (unsigned int)(duration > ranking->children[open] ? duration - ranking->children[open] : 0); + int slot; + + for (slot = ranking->count; slot > 0 && ranking->own[slot - 1] < own; slot--) + { + if (slot < PROFILE_JSON_LONGEST_CHILDREN) + { + ranking->longest[slot] = ranking->longest[slot - 1]; + ranking->own[slot] = ranking->own[slot - 1]; + } + } + if (slot < PROFILE_JSON_LONGEST_CHILDREN) + { + ranking->longest[slot] = scope; + ranking->own[slot] = own; + if (ranking->count < PROFILE_JSON_LONGEST_CHILDREN) + ranking->count++; + } + if (open > 0) + ranking->children[open - 1] += duration; +} + +static void profile_json_cpu_summary( + const struct profile_part *part, + FILE *file) +{ + struct profile_json_name_totals totals[MAXIMUM_PROFILE_TRACE_NAMES]; + const struct profile_trace_record *game = part->records[_profile_track_game]; + unsigned long game_count = part->record_counts[_profile_track_game]; + unsigned long worst[PROFILE_JSON_WORST_FRAMES]; + long worst_frame_number[PROFILE_JSON_WORST_FRAMES]; + int worst_count = 0; + struct profile_json_ranking ranking; + int frame_name = profile_json_name_of(part, "frame"); + int tick_name = profile_json_name_of(part, "game_tick"); + struct profile_json_list list; + unsigned long index; + long frames = 0; + int track, name; + + memset(totals, 0, sizeof(totals)); + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + for (index = 0; index < part->record_counts[track]; index++) + { + const struct profile_trace_record *record = &part->records[track][index]; + struct profile_json_name_totals *name_totals; + + if (record->name >= MAXIMUM_PROFILE_TRACE_NAMES) + continue; + name_totals = &totals[record->name]; + if (record->depth < MAXIMUM_PROFILE_TRACE_DEPTH || record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_TIME) + { + name_totals->total += record->duration; + if (record->duration > name_totals->maximum) + name_totals->maximum = record->duration; + } + if (record->depth < MAXIMUM_PROFILE_TRACE_DEPTH) + name_totals->count++; + else if (record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_COUNT) + name_totals->count += record->duration; + } + } + /* the worst frames: the game track is sorted, so a frame's children + follow it */ + for (index = 0; index < game_count; index++) + { + int slot; + + if (game[index].depth >= MAXIMUM_PROFILE_TRACE_DEPTH || game[index].name != frame_name) + continue; + frames++; + for (slot = worst_count; slot > 0 && game[worst[slot - 1]].duration < game[index].duration; slot--) + { + if (slot < PROFILE_JSON_WORST_FRAMES) + { + worst[slot] = worst[slot - 1]; + worst_frame_number[slot] = worst_frame_number[slot - 1]; + } + } + if (slot < PROFILE_JSON_WORST_FRAMES) + { + worst[slot] = index; + worst_frame_number[slot] = part->first_frame + frames - 1; + if (worst_count < PROFILE_JSON_WORST_FRAMES) + worst_count++; + } + } + + fprintf(file, "{\"frames\": %ld, \"ticks\": %ld, \"columns\": [\"name\", \"count\", \"total_ms\", " + "\"mean_ms\", \"max_ms\", \"per_frame\", \"per_tick_ms\"], \"rows\": [\n", frames, part->ticks); + list.file = file; + list.items = 0; + for (name = 0; name < part->name_count && name < MAXIMUM_PROFILE_TRACE_NAMES; name++) + { + const char *text = profile_trace_name_text(name); + struct profile_json_name_totals const *name_totals = &totals[name]; + int per_tick = strncmp(text, "game_tick", 9) == 0 || strncmp(text, "network_distributed_tick", 24) == 0; + + if (!name_totals->count) + continue; + profile_json_item(&list); + fputc('[', file); + profile_json_string(file, text); + fprintf(file, ", %llu, %.3f, %.4f, %.3f, %.3f, ", name_totals->count, name_totals->total / 1e6, + name_totals->total / 1e6 / (double)name_totals->count, name_totals->maximum / 1e6, + frames ? (double)name_totals->count / (double)frames : 0.0); + if (per_tick && part->ticks) + fprintf(file, "%.4f]", name_totals->total / 1e6 / (double)part->ticks); + else + fputs("null]", file); + } + fputs(list.items ? "\n]" : "]", file); + + fputs(", \"worst_frames\": {\"columns\": [\"frame\", \"at_s\", \"frame_ms\", \"ticks\", \"longest\"], \"rows\": [\n", file); + list.items = 0; + for (index = 0; index < (unsigned long)worst_count; index++) + { + const struct profile_trace_record *frame = &game[worst[index]]; + unsigned long long end = frame->start + frame->duration; + int ticks = 0; + unsigned long child; + int slot; + + /* (a tick sits under whatever the main loop wraps it in, so every + depth of the frame counts; the scopes are ranked by the time they have + of their own, or the parents, which hold all of it, would always come + first. The open scopes are a stack, so nothing is allocated for it) */ + memset(&ranking, 0, sizeof(ranking)); + for (child = worst[index] + 1; child < game_count && game[child].start < end; child++) + { + if (game[child].depth >= MAXIMUM_PROFILE_TRACE_DEPTH || game[child].depth <= frame->depth) + continue; + if (game[child].name == tick_name) + ticks++; + while (ranking.open && game[ranking.scope[ranking.open - 1]].depth >= game[child].depth) + profile_json_close(&ranking, game); + ranking.scope[ranking.open] = child; + ranking.children[ranking.open++] = 0; + } + while (ranking.open) + profile_json_close(&ranking, game); + profile_json_item(&list); + fprintf(file, "[%ld, %.3f, %.3f, %d, [", worst_frame_number[index], frame->start / 1e9, frame->duration / 1e6, + ticks); + for (slot = 0; slot < ranking.count; slot++) + { + fputs(slot ? ", [" : "[", file); + profile_json_string(file, profile_trace_name_text(game[ranking.longest[slot]].name)); + fprintf(file, ", %.3f]", ranking.own[slot] / 1e6); + } + fputs("]]", file); + } + fputs(list.items ? "\n]}}" : "]}}", file); +} + +static void profile_json_event( + FILE *file, + struct profile_json_list *list, + const struct profile_trace_record *record) +{ + const char *name = profile_trace_name_text(record->name); + + profile_json_item(list); + switch (record->depth) + { + case PROFILE_TRACE_DEPTH_AGGREGATE_TIME: + case PROFILE_TRACE_DEPTH_AGGREGATE_COUNT: + fputs("{\"ph\":\"C\",\"name\":\"", file); + profile_json_escaped(file, name); + fputs(record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_TIME ? "_ms\",\"pid\":1,\"tid\":1,\"ts\":" : + "_count\",\"pid\":1,\"tid\":1,\"ts\":", file); + profile_json_time(file, record->start); + if (record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_TIME) + fprintf(file, ",\"args\":{\"value\":%.4f}}", record->duration / 1e6); + else + fprintf(file, ",\"args\":{\"value\":%u}}", record->duration); + break; + default: + fputs("{\"ph\":\"X\",\"name\":", file); + profile_json_string(file, name); + fprintf(file, ",\"pid\":1,\"tid\":%d,\"ts\":", record->track + 1); + profile_json_time(file, record->start); + fputs(",\"dur\":", file); + profile_json_time(file, record->duration); + fputc('}', file); + break; + } +} + +/* ---------- public code */ + +int profile_json_write( + struct profile_part *part, + FILE *file) +{ + struct profile_json_list list; + unsigned long next[NUMBER_OF_PROFILE_TRACKS] = { 0, 0 }; + int track; + + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + if (part->record_counts[track]) + { + qsort(part->records[track], part->record_counts[track], sizeof(struct profile_trace_record), + profile_json_compare_records); + } + } + + fputs("{\"halo\": {\n", file); + profile_json_header(part, file); + fputs("},\n\"cpu_summary\": ", file); + profile_json_cpu_summary(part, file); + fputs(",\n\"traceEvents\": [\n", file); + + list.file = file; + list.items = 0; + profile_json_item(&list); + fprintf(file, "{\"ph\":\"M\",\"name\":\"process_name\",\"pid\":1,\"args\":{\"name\":\"halo %s %s\"}}", + part->session.role, part->session.platform); + profile_json_item(&list); + fputs("{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":1,\"tid\":1,\"args\":{\"name\":\"game\"}}", file); + profile_json_item(&list); + fputs("{\"ph\":\"M\",\"name\":\"thread_name\",\"pid\":1,\"tid\":2,\"args\":{\"name\":\"p2p\"}}", file); + if (part->number == 1) + { + profile_json_item(&list); + fputs("{\"ph\":\"i\",\"name\":\"recording_start\",\"s\":\"g\",\"pid\":1,\"tid\":1,\"ts\":0.000}", file); + } + /* the two tracks merged, in order of start and depth: each scope after + its parents */ + for (;;) + { + const struct profile_trace_record *game = next[0] < part->record_counts[0] ? &part->records[0][next[0]] : NULL; + const struct profile_trace_record *p2p = next[1] < part->record_counts[1] ? &part->records[1][next[1]] : NULL; + + if (!game && !p2p) + break; + if (game && (!p2p || profile_json_compare_records(game, p2p) <= 0)) + { + profile_json_event(file, &list, game); + next[0]++; + } + else + { + profile_json_event(file, &list, p2p); + next[1]++; + } + } + if (part->last) + { + profile_json_item(&list); + fputs("{\"ph\":\"i\",\"name\":\"recording_stop\",\"s\":\"g\",\"pid\":1,\"tid\":1,\"ts\":", file); + profile_json_time(file, part->end_ns); + fprintf(file, ",\"args\":{\"reason\":\"%s\"}}", profile_json_stop_reasons[part->stop_reason]); + } + fputs("\n],\n\"displayTimeUnit\": \"ms\"}\n", file); + return !ferror(file); +} + +void profile_json_choose_name( + const char *folder, + const char *stamp, + const char *role, + char *name, + int size) +{ + char path[512]; + int suffix; + + snprintf(name, (size_t)size, "profile_%s_%s", stamp, role); + for (suffix = 2; suffix < 1000; suffix++) + { + FILE *file; + int occupied = 0; + + snprintf(path, sizeof(path), "%s/%s.part1.json", folder, name); + file = fopen(path, "rb"); + if (file) + { + fclose(file); + occupied = 1; + } + if (!occupied) + break; + snprintf(name, (size_t)size, "profile_%s_%s_%d", stamp, role, suffix); + } +} + +int profile_json_write_part( + struct profile_part *part) +{ + char temporary[520]; + char path[512]; + FILE *file; + int written; + + snprintf(path, sizeof(path), "%s/%s.part%ld.json", part->folder, part->name, part->number); + snprintf(temporary, sizeof(temporary), "%s.tmp", path); + file = fopen(temporary, "wb"); + if (!file) + { + profile_trace_log("cannot write %s", temporary); + return 0; + } + written = profile_json_write(part, file); + if (fclose(file) != 0) + written = 0; + /* (Windows' rename does not replace a file: the recording's name was + chosen not to be there) */ + if (written && rename(temporary, path) != 0) + written = 0; + if (!written) + { + remove(temporary); + profile_trace_log("cannot write %s", path); + return 0; + } + profile_trace_log("wrote %s", path); + return 1; +} + +static void *profile_json_writer( + void *unused) +{ + (void)unused; + for (;;) + { + struct profile_part *part = profile_trace_writer_next(); + int last = part->last; + profile_json_write_part(part); + profile_trace_writer_done(part); + if (last) + break; + } + return NULL; +} + +int profile_json_writer_start( + void) +{ + pthread_attr_t attributes; + pthread_t thread; + int started; + + pthread_attr_init(&attributes); + pthread_attr_setdetachstate(&attributes, PTHREAD_CREATE_DETACHED); + started = pthread_create(&thread, &attributes, profile_json_writer, NULL) == 0; + pthread_attr_destroy(&attributes); + return started; +} + +#endif diff --git a/port/linux/src/profile_part.h b/port/linux/src/profile_part.h new file mode 100644 index 00000000..d85c412b --- /dev/null +++ b/port/linux/src/profile_part.h @@ -0,0 +1,97 @@ +/* +PROFILE_PART.H + +Define frozen recording parts shared by the recorder and writer. +*/ + +#ifndef __PROFILE_PART_H +#define __PROFILE_PART_H + +#ifdef HALO_PROFILE + +#include "profile_trace.h" + +#include + +/* ---------- constants */ + +/* records that are not scopes, by their depth (a scope's is under +MAXIMUM_PROFILE_TRACE_DEPTH): an aggregate name's time and count over a +frame (start: the frame's) */ +enum +{ + PROFILE_TRACE_DEPTH_AGGREGATE_TIME = 255, + PROFILE_TRACE_DEPTH_AGGREGATE_COUNT = 254, +}; + +/* ---------- structures */ + +/* a scope that ended: 16 bytes */ +struct profile_trace_record +{ + /* nanoseconds since the recording started */ + unsigned long long start; + /* nanoseconds, saturating (or the counter's value) */ + unsigned int duration; + unsigned short name; + unsigned char depth; + unsigned char track; +}; + +struct profile_part +{ + char name[64]; + char folder[260]; + long number; + int last; + int stop_reason; + int arena; + struct profile_trace_record *records[NUMBER_OF_PROFILE_TRACKS]; + unsigned long record_counts[NUMBER_OF_PROFILE_TRACKS]; + unsigned long long start_ns; + unsigned long long end_ns; + long first_frame; + long frames; + long first_tick; + long ticks; + long name_count; + struct profile_trace_session session; + char start_utc[32]; + double clock_read_ns; + unsigned long memory_used; + unsigned long memory_limit; + double writer_wait_ms; + unsigned long foreign_scopes; + unsigned long deep_scopes; + unsigned long unbalanced_scopes; + unsigned long dropped_scopes; +}; + +typedef char profile_trace_record_size_assert[sizeof(struct profile_trace_record) == 16 ? 1 : -1]; + +/* ---------- prototypes/PROFILE_TRACE.C */ + +const char *profile_trace_name_text(int name); +int profile_trace_name_is_aggregate(int name); +/* the writer: the next part (waits for one), and a part written (its +arena back; after the last, both arenas freed and the recording over) */ +struct profile_part *profile_trace_writer_next(void); +/* a line in the log (profile_trace_set_log) */ +void profile_trace_log(const char *format, ...); +void profile_trace_writer_done(struct profile_part *part); + +/* ---------- prototypes/PROFILE_JSON.C */ + +/* a part as a Chrome trace with the "halo" and "cpu_summary" keys; 0 when +the file could not be written */ +int profile_json_write(struct profile_part *part, FILE *file); +/* Part names keep profile__. */ +void profile_json_choose_name(const char *folder, const char *stamp, const char *role, char *name, int size); +/* the writer thread of a recording: 0 when it cannot start */ +int profile_json_writer_start(void); +/* a part's file: /.part.json, written as .tmp and renamed */ +int profile_json_write_part(struct profile_part *part); + +#endif + +#endif diff --git a/port/linux/src/profile_trace.c b/port/linux/src/profile_trace.c new file mode 100644 index 00000000..7af3c511 --- /dev/null +++ b/port/linux/src/profile_trace.c @@ -0,0 +1,1006 @@ +/* +PROFILE_TRACE.C + +Record bounded CPU traces and hand frozen parts to the writer. +*/ + +#ifdef HALO_PROFILE + +#include "profile_part.h" + +#include +#include +#include +#include +#include +#include + +/* state changes happen only at the game frame boundary. The recording flag +and track regions change under the p2p lock. two arenas let the writer own +one frozen part while the game and p2p threads fill the other. */ + +/* ---------- constants */ + +enum +{ + /* a region is cut when no more than this share of it is left (a + sixteenth: what a frame adds must still fit) */ + PROFILE_TRACE_HEADROOM_SHIFT = 4, + PROFILE_TRACE_CLOCK_SAMPLES = 1000, +}; + +/* ---------- structures */ + +struct profile_trace_open +{ + unsigned long long start; + unsigned short name; + /* begun while recording: only those are written */ + unsigned char recorded; +}; + +struct profile_trace_track +{ + int index; + struct profile_trace_record *records; + unsigned long count; + unsigned long capacity; + struct profile_trace_open stack[MAXIMUM_PROFILE_TRACE_DEPTH]; + int depth; + int open_aggregates; + /* scopes begun past the stack's depth and not yet ended */ + int overflow; + /* the track's own counts (no other thread writes them) */ + unsigned long deep; + unsigned long unbalanced; + unsigned long dropped; +}; + +struct profile_trace_aggregate +{ + int name; + unsigned long long time; + unsigned long count; +}; + +/* ---------- prototypes */ + +static unsigned long long profile_trace_default_clock(void); +static void profile_trace_no_lock(void); +static void *profile_trace_default_allocate(unsigned long size); +static void profile_trace_default_log(const char *text); +static void profile_trace_no_notify(const char *text); +static int profile_trace_always_ready(void); +static void profile_trace_default_session(struct profile_trace_session *session); +static void profile_trace_default_session_sampler(struct profile_trace_session *session); +static void profile_trace_sample_session(void); + +/* ---------- globals */ + +static struct +{ + unsigned long long (*now)(void); + void (*lock)(void); + void (*unlock)(void); + void *(*allocate)(unsigned long size); + void (*release)(void *block); + void (*emit)(const char *text); + void (*notify)(const char *text); + int (*start_writer)(void); + int (*ready)(void); + void (*describe)(struct profile_trace_session *session); + void (*sample)(struct profile_trace_session *session); +} profile_trace_seams = +{ + profile_trace_default_clock, + profile_trace_no_lock, + profile_trace_no_lock, + profile_trace_default_allocate, + free, + profile_trace_default_log, + profile_trace_no_notify, + profile_json_writer_start, + profile_trace_always_ready, + profile_trace_default_session, + profile_trace_default_session_sampler, +}; + +/* the names, for the whole run (profile.c keeps their ids) */ +static pthread_mutex_t profile_trace_names_lock = PTHREAD_MUTEX_INITIALIZER; +static const char *profile_trace_names[MAXIMUM_PROFILE_TRACE_NAMES]; +static unsigned char profile_trace_aggregate_names[MAXIMUM_PROFILE_TRACE_NAMES]; +static int profile_trace_name_count; +static struct profile_trace_aggregate profile_trace_aggregates[MAXIMUM_PROFILE_TRACE_AGGREGATES]; +static int profile_trace_aggregate_count; +static int profile_trace_wait_name = -1; + +static struct profile_trace_track profile_trace_tracks[NUMBER_OF_PROFILE_TRACKS]; +static __thread struct profile_trace_track *profile_trace_thread_track; +/* scopes from threads with no track (any thread: atomically) */ +static unsigned long profile_trace_foreign_scopes; + +static struct +{ + int state; + /* stored by the writer alone, once it has freed the arenas */ + int finished; + int rearm; + int when; + double seconds; + long memory_megabytes; + int stop_reason; + int map_loaded; + int name_chosen; + /* the tracks append; changed under the track lock */ + int recording; + unsigned long long origin; + unsigned long long frame_start; + void *arenas[2]; + unsigned long arena_size; + unsigned long game_bytes; + unsigned long p2p_bytes; + struct profile_part parts[2]; + int current; + long part_number; + long frame; + long tick; + unsigned long long next_session_sample; + char name[64]; + struct profile_trace_session session; + char start_utc[32]; + double clock_read_ns; + double writer_wait_ms; + /* the hand-off with the writer: which arenas it holds, and the parts + queued for it */ + pthread_mutex_t writer_lock; + pthread_cond_t writer_changed; + int writer_holds[2]; + struct profile_part *queue[2]; + int queue_count; +} profile_trace_globals = +{ + .state = _profile_trace_idle, + .memory_megabytes = DEFAULT_PROFILE_TRACE_MEMORY, + .writer_lock = PTHREAD_MUTEX_INITIALIZER, + .writer_changed = PTHREAD_COND_INITIALIZER, +}; + +/* ---------- private code */ + +static unsigned long long profile_trace_default_clock(void) +{ + struct timespec now; + + clock_gettime(CLOCK_MONOTONIC, &now); + return (unsigned long long)now.tv_sec * 1000000000ULL + (unsigned long long)now.tv_nsec; +} + +static void profile_trace_no_lock(void) +{ +} + +static void *profile_trace_default_allocate(unsigned long size) +{ + return malloc(size); +} + +static void profile_trace_default_log(const char *text) +{ + fprintf(stderr, "profile: %s\n", text); +} + +static void profile_trace_no_notify(const char *text) +{ + (void)text; +} + +static int profile_trace_always_ready(void) +{ + return 1; +} + +static void profile_trace_default_session(struct profile_trace_session *session) +{ + memset(session, 0, sizeof(*session)); + strcpy(session->folder, "."); + strcpy(session->role, "local"); + session->own_machine = -1; + strcpy(session->gametype, "none"); +} + +static void profile_trace_default_session_sampler(struct profile_trace_session *session) +{ + (void)session; +} + +static void profile_trace_sample_session(void) +{ + struct profile_trace_session current; + unsigned long long now = profile_trace_seams.now(); + + if (now < profile_trace_globals.next_session_sample) + return; + profile_trace_globals.next_session_sample = now + 1000000000ULL; + memset(¤t, 0, sizeof(current)); + profile_trace_seams.sample(¤t); + if (!profile_trace_globals.session.map_name[0] && current.map_name[0]) + { + strcpy(profile_trace_globals.session.map, current.map); + strcpy(profile_trace_globals.session.map_name, current.map_name); + strcpy(profile_trace_globals.session.gametype, current.gametype); + } + if (current.players > profile_trace_globals.session.players_most) + profile_trace_globals.session.players_most = current.players; +} + +static const char *profile_trace_platform(void) +{ +#if defined(HALO_ANDROID) + return "android"; +#elif defined(_WIN32) + return "windows"; +#else + return "linux"; +#endif +} + +static int profile_trace_is_recording(void) +{ + return __atomic_load_n(&profile_trace_globals.recording, __ATOMIC_RELAXED); +} + +static void profile_trace_append( + struct profile_trace_track *track, + unsigned long long start, + unsigned long long duration, + int name, + int depth) +{ + struct profile_trace_record *record; + + if (!track->records || track->count >= track->capacity) + { + track->dropped++; + return; + } + record = &track->records[track->count]; + /* (the game thread reads the p2p track's count at the frame boundary, + without its lock) */ + __atomic_store_n(&track->count, track->count + 1, __ATOMIC_RELAXED); + record->start = start; + record->duration = duration > 0xFFFFFFFFULL ? 0xFFFFFFFFU : (unsigned int)duration; + record->name = (unsigned short)name; + record->depth = (unsigned char)depth; + record->track = (unsigned char)track->index; +} + +static int profile_trace_track_full( + struct profile_trace_track const *track) +{ + unsigned long count = __atomic_load_n(&track->count, __ATOMIC_RELAXED); + + return count + (track->capacity >> PROFILE_TRACE_HEADROOM_SHIFT) >= track->capacity; +} + +/* the arena's part n: the tracks write to its regions (under the track +lock: the p2p thread reads them) */ +static void profile_trace_open_part( + int arena, + unsigned long long now) +{ + struct profile_part *part = &profile_trace_globals.parts[arena]; + char *base = profile_trace_globals.arenas[arena]; + struct profile_trace_track *game = &profile_trace_tracks[_profile_track_game]; + struct profile_trace_track *p2p = &profile_trace_tracks[_profile_track_p2p]; + + memset(part, 0, sizeof(*part)); + part->arena = arena; + part->number = profile_trace_globals.part_number; + part->start_ns = now - profile_trace_globals.origin; + part->first_frame = profile_trace_globals.frame; + part->first_tick = profile_trace_globals.tick; + game->records = (struct profile_trace_record *)base; + game->capacity = profile_trace_globals.game_bytes / sizeof(struct profile_trace_record); + game->count = 0; + p2p->records = (struct profile_trace_record *)(base + profile_trace_globals.game_bytes); + p2p->capacity = profile_trace_globals.p2p_bytes / sizeof(struct profile_trace_record); + p2p->count = 0; + part->records[_profile_track_game] = game->records; + part->records[_profile_track_p2p] = p2p->records; + profile_trace_globals.current = arena; +} + +static void profile_trace_emit_aggregates( + void) +{ + struct profile_trace_track *game = &profile_trace_tracks[_profile_track_game]; + unsigned long long start = profile_trace_globals.frame_start - profile_trace_globals.origin; + int index; + + for (index = 0; index < profile_trace_aggregate_count; index++) + { + struct profile_trace_aggregate *aggregate = &profile_trace_aggregates[index]; + + if (!aggregate->count) + continue; + profile_trace_append(game, start, aggregate->time, aggregate->name, PROFILE_TRACE_DEPTH_AGGREGATE_TIME); + profile_trace_append(game, start, aggregate->count, aggregate->name, PROFILE_TRACE_DEPTH_AGGREGATE_COUNT); + aggregate->time = 0; + aggregate->count = 0; + } +} + +/* the current part frozen and queued for the writer: the last of the +recording, or the tracks go on in the other arena (once the writer has +given it back: the game thread waits for it here, and the wait is a +profile_wait scope in the new part) */ +static void profile_trace_cut( + int last, + int reason) +{ + struct profile_part *part = &profile_trace_globals.parts[profile_trace_globals.current]; + int next = 1 - profile_trace_globals.current; + unsigned long long now; + unsigned long long wait_start = 0; + unsigned long long waited = 0; + int track; + + profile_trace_emit_aggregates(); + /* (a map load that stops the recording already names the next map: a + recording that never learnt its map stays without one rather than take + that one) */ + if (!(last && reason == _profile_trace_stop_map_load)) + { + profile_trace_globals.next_session_sample = 0; + profile_trace_sample_session(); + } + if (!last) + { + pthread_mutex_lock(&profile_trace_globals.writer_lock); + if (profile_trace_globals.writer_holds[next]) + { + wait_start = profile_trace_seams.now(); + while (profile_trace_globals.writer_holds[next]) + pthread_cond_wait(&profile_trace_globals.writer_changed, &profile_trace_globals.writer_lock); + waited = profile_trace_seams.now() - wait_start; + } + pthread_mutex_unlock(&profile_trace_globals.writer_lock); + profile_trace_globals.writer_wait_ms += (double)waited / 1000000.0; + } + + profile_trace_seams.lock(); + /* (read under the lock, after the wait for the writer: the p2p thread appends to this + arena until here, and every record it appended ended before this time) */ + now = profile_trace_seams.now(); + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + struct profile_trace_track *source = &profile_trace_tracks[track]; + + part->record_counts[track] = source->count; + part->deep_scopes += source->deep; + part->unbalanced_scopes += source->unbalanced; + part->dropped_scopes += source->dropped; + source->deep = source->unbalanced = source->dropped = 0; + } + if (last) + { + __atomic_store_n(&profile_trace_globals.recording, 0, __ATOMIC_RELAXED); + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + profile_trace_tracks[track].records = NULL; + profile_trace_tracks[track].capacity = 0; + profile_trace_tracks[track].count = 0; + } + } + else + { + profile_trace_globals.part_number++; + profile_trace_open_part(next, now); + } + profile_trace_seams.unlock(); + + part->last = last; + part->stop_reason = last ? reason : _profile_trace_stop_none; + part->end_ns = now - profile_trace_globals.origin; + part->frames = profile_trace_globals.frame - part->first_frame; + part->ticks = profile_trace_globals.tick - part->first_tick; + strcpy(part->name, profile_trace_globals.name); + strcpy(part->folder, profile_trace_globals.session.folder); + part->session = profile_trace_globals.session; + strcpy(part->session.platform, profile_trace_platform()); + strcpy(part->start_utc, profile_trace_globals.start_utc); + part->clock_read_ns = profile_trace_globals.clock_read_ns; + part->memory_used = (unsigned long)(part->record_counts[0] + part->record_counts[1]) * + sizeof(struct profile_trace_record); + part->memory_limit = profile_trace_globals.arena_size; + part->writer_wait_ms = profile_trace_globals.writer_wait_ms; + part->foreign_scopes = __atomic_exchange_n(&profile_trace_foreign_scopes, 0, __ATOMIC_RELAXED); + pthread_mutex_lock(&profile_trace_names_lock); + part->name_count = profile_trace_name_count; + pthread_mutex_unlock(&profile_trace_names_lock); + + if (!last && waited) + { + profile_trace_append(&profile_trace_tracks[_profile_track_game], wait_start - profile_trace_globals.origin, + now - wait_start, profile_trace_wait_name, 0); + } + + pthread_mutex_lock(&profile_trace_globals.writer_lock); + profile_trace_globals.writer_holds[part->arena] = 1; + profile_trace_globals.queue[profile_trace_globals.queue_count++] = part; + pthread_cond_broadcast(&profile_trace_globals.writer_changed); + pthread_mutex_unlock(&profile_trace_globals.writer_lock); + + if (last) + { + profile_trace_globals.state = _profile_trace_finishing; + profile_trace_log("writing %s, %ld parts", profile_trace_globals.name, profile_trace_globals.part_number); + } +} + +/* the recording's name, from the time and the machine's role: when it is +asked for (profile_record answers with it), or when a game starts */ +static void profile_trace_choose_name( + void) +{ + time_t wall = time(NULL); + struct tm *utc = gmtime(&wall); + char stamp[32]; + + profile_trace_seams.describe(&profile_trace_globals.session); + if (utc) + { + strftime(stamp, sizeof(stamp), "%Y%m%d-%H%M%S", utc); + strftime(profile_trace_globals.start_utc, sizeof(profile_trace_globals.start_utc), "%Y-%m-%d %H:%M:%S", utc); + } + else + { + strcpy(stamp, "00000000-000000"); + strcpy(profile_trace_globals.start_utc, ""); + } + profile_json_choose_name(profile_trace_globals.session.folder, stamp, profile_trace_globals.session.role, + profile_trace_globals.name, sizeof(profile_trace_globals.name)); + profile_trace_globals.session.players_most = profile_trace_globals.session.players; + profile_trace_globals.name_chosen = 1; +} + +static void profile_trace_start_recording( + void) +{ + unsigned long long memory = (unsigned long long)profile_trace_globals.memory_megabytes * 1024 * 1024; + unsigned long size = (unsigned long)(memory / 2) & ~63UL; + unsigned long scope_bytes = size; + unsigned long long now; + int track, sample; + + if (!profile_trace_globals.name_chosen) + profile_trace_choose_name(); + profile_trace_globals.name_chosen = 0; + profile_trace_globals.arenas[0] = profile_trace_seams.allocate(size); + profile_trace_globals.arenas[1] = profile_trace_globals.arenas[0] ? profile_trace_seams.allocate(size) : NULL; + if (!profile_trace_globals.arenas[1]) + { + char text[96]; + + if (profile_trace_globals.arenas[0]) + profile_trace_seams.release(profile_trace_globals.arenas[0]); + profile_trace_globals.arenas[0] = NULL; + snprintf(text, sizeof(text), "profile: no memory for %ld MB", profile_trace_globals.memory_megabytes); + profile_trace_log("%s", text + 9); + profile_trace_seams.notify(text); + profile_trace_globals.state = _profile_trace_idle; + profile_trace_globals.rearm = 0; + return; + } + profile_trace_globals.arena_size = size; + /* the scopes: seven eighths the game track's, an eighth + the p2p track's (whole records each) */ + profile_trace_globals.game_bytes = scope_bytes / 8 * 7 / sizeof(struct profile_trace_record) * + sizeof(struct profile_trace_record); + profile_trace_globals.p2p_bytes = (scope_bytes - profile_trace_globals.game_bytes) / + sizeof(struct profile_trace_record) * sizeof(struct profile_trace_record); + + __atomic_store_n(&profile_trace_foreign_scopes, 0, __ATOMIC_RELAXED); + for (track = 0; track < profile_trace_aggregate_count; track++) + { + profile_trace_aggregates[track].time = 0; + profile_trace_aggregates[track].count = 0; + } + profile_trace_globals.frame = 0; + profile_trace_globals.tick = 0; + profile_trace_globals.part_number = 1; + profile_trace_globals.writer_wait_ms = 0.0; + profile_trace_globals.stop_reason = _profile_trace_stop_none; + profile_trace_globals.writer_holds[0] = profile_trace_globals.writer_holds[1] = 0; + profile_trace_globals.queue_count = 0; + __atomic_store_n(&profile_trace_globals.finished, 0, __ATOMIC_RELAXED); + + now = profile_trace_seams.now(); + for (sample = 0; sample < PROFILE_TRACE_CLOCK_SAMPLES; sample++) + profile_trace_seams.now(); + profile_trace_globals.clock_read_ns = (double)(profile_trace_seams.now() - now) / PROFILE_TRACE_CLOCK_SAMPLES; + + now = profile_trace_seams.now(); + profile_trace_globals.origin = now; + profile_trace_globals.frame_start = now; + profile_trace_seams.lock(); + /* (under the lock: a p2p pass of the last recording may end, and count, meanwhile) */ + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + profile_trace_tracks[track].deep = 0; + profile_trace_tracks[track].unbalanced = 0; + profile_trace_tracks[track].dropped = 0; + } + profile_trace_open_part(0, now); + profile_trace_seams.unlock(); + if (!profile_trace_seams.start_writer()) + { + profile_trace_seams.lock(); + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + profile_trace_tracks[track].records = NULL; + profile_trace_seams.unlock(); + profile_trace_seams.release(profile_trace_globals.arenas[0]); + profile_trace_seams.release(profile_trace_globals.arenas[1]); + profile_trace_globals.arenas[0] = profile_trace_globals.arenas[1] = NULL; + profile_trace_log("the writer thread cannot start: not recording"); + profile_trace_seams.notify("profile: the writer thread cannot start"); + profile_trace_globals.state = _profile_trace_idle; + profile_trace_globals.rearm = 0; + return; + } + profile_trace_seams.lock(); + __atomic_store_n(&profile_trace_globals.recording, 1, __ATOMIC_RELAXED); + profile_trace_seams.unlock(); + profile_trace_globals.state = _profile_trace_recording; + profile_trace_log("recording %s", profile_trace_globals.name); +} + +/* ---------- public code */ + +void profile_trace_set_clock( + unsigned long long (*now_ns)(void)) +{ + profile_trace_seams.now = now_ns ? now_ns : profile_trace_default_clock; +} + +void profile_trace_set_track_lock( + void (*lock)(void), + void (*unlock)(void)) +{ + profile_trace_seams.lock = lock && unlock ? lock : profile_trace_no_lock; + profile_trace_seams.unlock = lock && unlock ? unlock : profile_trace_no_lock; +} + +void profile_trace_set_allocator( + void *(*allocate)(unsigned long size), + void (*release)(void *block)) +{ + profile_trace_seams.allocate = allocate && release ? allocate : profile_trace_default_allocate; + profile_trace_seams.release = allocate && release ? release : free; +} + +void profile_trace_set_log( + void (*log)(const char *text)) +{ + profile_trace_seams.emit = log ? log : profile_trace_default_log; +} + +void profile_trace_set_notify( + void (*notify)(const char *text)) +{ + profile_trace_seams.notify = notify ? notify : profile_trace_no_notify; +} + +void profile_trace_set_writer( + int (*start)(void)) +{ + profile_trace_seams.start_writer = start ? start : profile_json_writer_start; +} + +void profile_trace_set_ready( + int (*ready)(void)) +{ + profile_trace_seams.ready = ready ? ready : profile_trace_always_ready; +} + +void profile_trace_set_session( + void (*describe)(struct profile_trace_session *session)) +{ + profile_trace_seams.describe = describe ? describe : profile_trace_default_session; +} + +void profile_trace_set_session_sampler( + void (*sample)(struct profile_trace_session *session)) +{ + profile_trace_seams.sample = sample ? sample : profile_trace_default_session_sampler; +} + +void profile_trace_log( + const char *format, + ...) +{ + char text[512]; + va_list arguments; + + va_start(arguments, format); + vsnprintf(text, sizeof(text), format, arguments); + va_end(arguments); + profile_trace_seams.emit(text); +} + +void profile_trace_thread_register( + int track) +{ + if (track < 0 || track >= NUMBER_OF_PROFILE_TRACKS) + return; + profile_trace_tracks[track].index = track; + profile_trace_thread_track = &profile_trace_tracks[track]; +} + +int profile_trace_name( + const char *name) +{ + int index; + + if (!name) + return -1; + pthread_mutex_lock(&profile_trace_names_lock); + for (index = 0; index < profile_trace_name_count; index++) + { + if (strcmp(profile_trace_names[index], name) == 0) + break; + } + if (index == profile_trace_name_count) + { + if (index < MAXIMUM_PROFILE_TRACE_NAMES) + profile_trace_names[profile_trace_name_count++] = name; + else + index = -1; + } + pthread_mutex_unlock(&profile_trace_names_lock); + return index; +} + +void profile_trace_name_aggregate( + const char *name) +{ + int id = profile_trace_name(name); + + if (id < 0 || profile_trace_aggregate_names[id] || + profile_trace_aggregate_count >= MAXIMUM_PROFILE_TRACE_AGGREGATES) + { + return; + } + profile_trace_aggregates[profile_trace_aggregate_count].name = id; + profile_trace_aggregates[profile_trace_aggregate_count].time = 0; + profile_trace_aggregates[profile_trace_aggregate_count].count = 0; + profile_trace_aggregate_count++; + profile_trace_aggregate_names[id] = 1; +} + +const char *profile_trace_name_text( + int name) +{ + const char *text = "unknown"; + + pthread_mutex_lock(&profile_trace_names_lock); + if (name >= 0 && name < profile_trace_name_count) + text = profile_trace_names[name]; + pthread_mutex_unlock(&profile_trace_names_lock); + return text; +} + +int profile_trace_name_is_aggregate( + int name) +{ + return name >= 0 && name < MAXIMUM_PROFILE_TRACE_NAMES && profile_trace_aggregate_names[name]; +} + +void profile_trace_begin( + int name) +{ + struct profile_trace_track *track = profile_trace_thread_track; + struct profile_trace_open *open; + + if (!track) + { + if (profile_trace_is_recording()) + __atomic_fetch_add(&profile_trace_foreign_scopes, 1, __ATOMIC_RELAXED); + return; + } + if (name < 0) + return; + if (track->depth >= MAXIMUM_PROFILE_TRACE_DEPTH) + { + track->overflow++; + if (profile_trace_is_recording()) + track->deep++; + return; + } + open = &track->stack[track->depth++]; + open->name = (unsigned short)name; + open->recorded = (unsigned char)profile_trace_is_recording(); + open->start = open->recorded ? profile_trace_seams.now() : 0; + if (profile_trace_aggregate_names[name]) + track->open_aggregates++; +} + +void profile_trace_end( + int name) +{ + struct profile_trace_track *track = profile_trace_thread_track; + struct profile_trace_open *open; + unsigned long long duration; + + if (!track || name < 0) + return; + if (track->overflow) + { + track->overflow--; + return; + } + if (!track->depth || track->stack[track->depth - 1].name != name) + { + if (profile_trace_is_recording()) + track->unbalanced++; + return; + } + open = &track->stack[--track->depth]; + if (profile_trace_aggregate_names[name] && track->open_aggregates > 0) + track->open_aggregates--; + if (!open->recorded) + return; + /* (a scope that outlived its recording: the p2p thread lets go of its + lock for slow work, and a stop can come meanwhile) */ + if (!profile_trace_is_recording() || !track->records || open->start < profile_trace_globals.origin) + { + track->dropped++; + return; + } + duration = profile_trace_seams.now() - open->start; + if (profile_trace_aggregate_names[name]) + { + int index; + + if (track->index != _profile_track_game) + return; + for (index = 0; index < profile_trace_aggregate_count; index++) + { + if (profile_trace_aggregates[index].name == name) + { + profile_trace_aggregates[index].time += duration; + profile_trace_aggregates[index].count++; + break; + } + } + return; + } + { + /* (an aggregated parent leaves no record, so depth counts only the + recorded ancestors) */ + int depth = track->depth - track->open_aggregates; + profile_trace_append(track, open->start - profile_trace_globals.origin, duration, name, depth); + } +} + +void profile_trace_frame_boundary( + void) +{ + struct profile_trace_track *game = &profile_trace_tracks[_profile_track_game]; + unsigned long long now; + + /* (a scope the frame left open: its end is lost, and so is it) */ + if (game->depth || game->overflow) + { + if (profile_trace_is_recording()) + game->unbalanced += (unsigned long)(game->depth + game->overflow); + game->depth = 0; + game->open_aggregates = 0; + game->overflow = 0; + } + if (profile_trace_wait_name < 0) + profile_trace_wait_name = profile_trace_name("profile_wait"); + switch (profile_trace_globals.state) + { + case _profile_trace_armed: + if (profile_trace_globals.when == _profile_trace_when_now || profile_trace_seams.ready()) + profile_trace_start_recording(); + break; + case _profile_trace_recording: + now = profile_trace_seams.now(); + if (now >= profile_trace_globals.next_session_sample) + profile_trace_sample_session(); + profile_trace_emit_aggregates(); + profile_trace_globals.frame++; + profile_trace_globals.frame_start = now; + if (!profile_trace_globals.stop_reason && profile_trace_globals.seconds > 0.0 && + (double)(now - profile_trace_globals.origin) >= profile_trace_globals.seconds * 1000000000.0) + { + profile_trace_globals.stop_reason = _profile_trace_stop_seconds; + } + if (profile_trace_globals.stop_reason) + { + profile_trace_cut(1, profile_trace_globals.stop_reason); + } + else if (profile_trace_track_full(&profile_trace_tracks[_profile_track_game]) || + profile_trace_track_full(&profile_trace_tracks[_profile_track_p2p])) + { + profile_trace_cut(0, _profile_trace_stop_none); + } + break; + case _profile_trace_finishing: + if (__atomic_load_n(&profile_trace_globals.finished, __ATOMIC_ACQUIRE)) + { + __atomic_store_n(&profile_trace_globals.finished, 0, __ATOMIC_RELAXED); + profile_trace_globals.state = profile_trace_globals.rearm ? _profile_trace_armed : _profile_trace_idle; + } + break; + default: + break; + } +} + +void profile_trace_tick( + void) +{ + if (profile_trace_globals.state != _profile_trace_recording) + return; + profile_trace_globals.tick++; +} + +int profile_trace_request_start( + double seconds, + int when, + long memory_megabytes) +{ + switch (profile_trace_globals.state) + { + case _profile_trace_armed: + case _profile_trace_recording: + return _profile_trace_answer_already_recording; + case _profile_trace_finishing: + return _profile_trace_answer_still_writing; + default: + break; + } + if (memory_megabytes < MINIMUM_PROFILE_TRACE_MEMORY) + memory_megabytes = MINIMUM_PROFILE_TRACE_MEMORY; + if (memory_megabytes > MAXIMUM_PROFILE_TRACE_MEMORY) + memory_megabytes = MAXIMUM_PROFILE_TRACE_MEMORY; + profile_trace_globals.seconds = seconds > 0.0 ? seconds : 0.0; + profile_trace_globals.when = when; + profile_trace_globals.memory_megabytes = memory_megabytes; + profile_trace_globals.rearm = when == _profile_trace_when_game; + profile_trace_globals.stop_reason = _profile_trace_stop_none; + profile_trace_globals.state = _profile_trace_armed; + profile_trace_globals.name_chosen = 0; + if (when == _profile_trace_when_now) + profile_trace_choose_name(); + return _profile_trace_answer_armed; +} + +int profile_trace_request_stop( + void) +{ + switch (profile_trace_globals.state) + { + case _profile_trace_armed: + profile_trace_globals.state = _profile_trace_idle; + profile_trace_globals.rearm = 0; + return profile_trace_globals.when == _profile_trace_when_game ? _profile_trace_answer_disarmed : + _profile_trace_answer_not_recording; + case _profile_trace_recording: + profile_trace_globals.rearm = 0; + if (!profile_trace_globals.stop_reason) + profile_trace_globals.stop_reason = _profile_trace_stop_command; + return _profile_trace_answer_stopping; + case _profile_trace_finishing: + if (profile_trace_globals.rearm) + { + profile_trace_globals.rearm = 0; + return _profile_trace_answer_disarmed; + } + return _profile_trace_answer_not_recording; + default: + return _profile_trace_answer_not_recording; + } +} + +void profile_trace_map_loaded( + void) +{ + if (!profile_trace_globals.map_loaded) + { + profile_trace_globals.map_loaded = 1; + return; + } + if (profile_trace_globals.state == _profile_trace_recording && !profile_trace_globals.stop_reason) + profile_trace_globals.stop_reason = _profile_trace_stop_map_load; +} + +void profile_trace_shutdown( + void) +{ + struct profile_trace_track *game = &profile_trace_tracks[_profile_track_game]; + + /* (exit called on another thread: the game thread may be mid-frame, + writing to the arena; the part being recorded is lost, as when the + process is killed) */ + if (profile_trace_thread_track != game) + return; + profile_trace_globals.rearm = 0; + if (profile_trace_globals.state == _profile_trace_armed) + profile_trace_globals.state = _profile_trace_idle; + if (profile_trace_globals.state == _profile_trace_recording) + { + game->depth = 0; + game->open_aggregates = 0; + game->overflow = 0; + profile_trace_cut(1, _profile_trace_stop_exit); + } + if (profile_trace_globals.state == _profile_trace_finishing) + { + pthread_mutex_lock(&profile_trace_globals.writer_lock); + while (!__atomic_load_n(&profile_trace_globals.finished, __ATOMIC_ACQUIRE)) + pthread_cond_wait(&profile_trace_globals.writer_changed, &profile_trace_globals.writer_lock); + pthread_mutex_unlock(&profile_trace_globals.writer_lock); + __atomic_store_n(&profile_trace_globals.finished, 0, __ATOMIC_RELAXED); + profile_trace_globals.state = _profile_trace_idle; + } +} + +int profile_trace_recording( + void) +{ + return profile_trace_is_recording(); +} + +void profile_trace_status( + struct profile_trace_status *status) +{ + memset(status, 0, sizeof(*status)); + status->state = profile_trace_globals.state; + strcpy(status->name, profile_trace_globals.name); + if (profile_trace_globals.state != _profile_trace_recording) + return; + status->part = profile_trace_globals.part_number; +} + +struct profile_part *profile_trace_writer_next( + void) +{ + struct profile_part *part; + + pthread_mutex_lock(&profile_trace_globals.writer_lock); + while (!profile_trace_globals.queue_count) + pthread_cond_wait(&profile_trace_globals.writer_changed, &profile_trace_globals.writer_lock); + part = profile_trace_globals.queue[0]; + profile_trace_globals.queue[0] = profile_trace_globals.queue[1]; + profile_trace_globals.queue_count--; + pthread_mutex_unlock(&profile_trace_globals.writer_lock); + return part; +} + +void profile_trace_writer_done( + struct profile_part *part) +{ + int last = part->last; + + pthread_mutex_lock(&profile_trace_globals.writer_lock); + profile_trace_globals.writer_holds[part->arena] = 0; + pthread_cond_broadcast(&profile_trace_globals.writer_changed); + pthread_mutex_unlock(&profile_trace_globals.writer_lock); + if (!last) + return; + /* (the last part: no track writes to either arena any more, and the + writer has written the other part before this one) */ + profile_trace_seams.release(profile_trace_globals.arenas[0]); + profile_trace_seams.release(profile_trace_globals.arenas[1]); + profile_trace_globals.arenas[0] = profile_trace_globals.arenas[1] = NULL; + pthread_mutex_lock(&profile_trace_globals.writer_lock); + __atomic_store_n(&profile_trace_globals.finished, 1, __ATOMIC_RELEASE); + pthread_cond_broadcast(&profile_trace_globals.writer_changed); + pthread_mutex_unlock(&profile_trace_globals.writer_lock); +} + +#endif diff --git a/source/cseries/profile.c b/source/cseries/profile.c index 0ef43da2..6f536996 100644 --- a/source/cseries/profile.c +++ b/source/cseries/profile.c @@ -278,6 +278,11 @@ symbols in this file: #include +#ifdef HALO_PROFILE +#include "profile_console.h" +#include "profile_trace.h" +#endif + /* ---------- constants */ enum @@ -448,6 +453,24 @@ boolean profile_global_enable = FALSE; boolean profile_dump_frames = FALSE; boolean profile_dump_lost_frames = FALSE; +#ifdef HALO_PROFILE +/* port: the profiling build: each section's name in the trace +(port/linux/src/profile_trace.c) by section_index, as struct +profile_section's size is fixed (profile.h's assertions); the frame +timers' names; and whether the first frame has set the recording up */ +static short profile_trace_section_names[MAXIMUM_PROFILE_SECTIONS]; +static struct +{ + int frame; + int game_tick; + int render; + int render_window; + int idle; + int texture; +} profile_trace_timer_names; +static boolean profile_trace_launched; +#endif + /* ---------- public code */ void profile_dump_to_file( @@ -1075,16 +1098,60 @@ void profile_initialize( profile_globals.lost_frame_count = 999; profile_globals.framedump_file = NULL; +#ifdef HALO_PROFILE + profile_trace_timer_names.frame = profile_trace_name("frame"); + profile_trace_timer_names.game_tick = profile_trace_name("game_tick"); + profile_trace_timer_names.render = profile_trace_name("render"); + profile_trace_timer_names.render_window = profile_trace_name("render_window"); + profile_trace_timer_names.idle = profile_trace_name("idle"); + profile_trace_timer_names.texture = profile_trace_name("texture"); + /* (many times a frame: a record each would cost more than the work it + times, so a count and a total a frame) */ + profile_trace_name_aggregate("texture"); + profile_trace_name_aggregate("render_model"); + profile_trace_name_aggregate("memory_dynamic_array_resize"); + profile_trace_name_aggregate("memory_dynamic_array_add_element"); + profile_trace_name_aggregate("memory_dynamic_array_delete_element"); + profile_trace_name_aggregate("item_update"); + profile_trace_name_aggregate("weapon_update"); + profile_trace_name_aggregate("unit_update"); + profile_trace_name_aggregate("biped_update"); + profile_trace_name_aggregate("vehicle_update"); + profile_trace_name_aggregate("projectile_update"); + profile_trace_name_aggregate("render_structure_shadows"); + profile_trace_name_aggregate("render_structure_shadows_draw"); + profile_trace_name_aggregate("render_structure_diffuse_lights"); + profile_trace_name_aggregate("render_structure_diffuse_lights_draw"); + profile_trace_name_aggregate("render_structure_specular_lights"); + profile_trace_name_aggregate("render_structure_specular_lights_draw"); +#endif + return; } void profile_frame_start( void) { +#ifdef HALO_PROFILE + if (!profile_trace_launched) + { + profile_trace_launched = TRUE; + profile_console_launch(); + } + /* (no section is open here: where a recording starts, is cut and + stops) */ + profile_trace_frame_boundary(); + profile_console_frame(); +#endif if (!profile_timebase_ticks) { profile_internal_step(); } +#ifdef HALO_PROFILE + /* (after the step, which rolls up what the sections timed last frame: + the console no longer turns it off mid-frame, console.c) */ + profile_global_enable = profile_trace_recording(); +#endif csmemset(&profile_globals.current_frame, 0, sizeof(profile_globals.current_frame)); @@ -1092,6 +1159,9 @@ void profile_frame_start( profile_globals.current_frame.vertical_blank_index = rasterizer_globals.vertical_blank_index; profile_globals.current_frame.game_tick_count = 0; profile_timesection_begin_now(&profile_globals.current_frame.frame); +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_timer_names.frame); +#endif return; } @@ -1118,6 +1188,10 @@ void profile_tick_start( timer = &profile_globals.current_frame.game_ticks[profile_globals.current_frame.game_tick_count-1]; profile_timesection_begin_now(timer); +#ifdef HALO_PROFILE + profile_trace_tick(); + profile_trace_begin(profile_trace_timer_names.game_tick); +#endif return; } @@ -1132,6 +1206,9 @@ void profile_tick_end( timer = &profile_globals.current_frame.game_ticks[profile_globals.current_frame.game_tick_count-1]; profile_timesection_end_now(timer); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.game_tick); +#endif return; } @@ -1154,6 +1231,9 @@ void profile_render_window_start( timer = &profile_globals.current_frame.windows[profile_globals.current_frame.window_count-1]; profile_timesection_begin_now(timer); +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_timer_names.render_window); +#endif return; } @@ -1168,6 +1248,9 @@ void profile_render_window_end( timer = &profile_globals.current_frame.windows[profile_globals.current_frame.window_count-1]; profile_timesection_end_now(timer); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.render_window); +#endif return; } @@ -1177,6 +1260,9 @@ void profile_render_start( { profile_globals.current_frame.window_count = 0; profile_timesection_begin_now(&profile_globals.current_frame.render); +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_timer_names.render); +#endif return; } @@ -1185,6 +1271,9 @@ void profile_render_end( void) { profile_timesection_end_now(&profile_globals.current_frame.render); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.render); +#endif return; } @@ -1200,6 +1289,9 @@ void profile_texture_start( if (PROFILE_TEXTURE_TIMED()) { profile_timesection_begin_now(&profile_globals.current_frame.texture); +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_timer_names.texture); +#endif } return; @@ -1211,6 +1303,9 @@ void profile_texture_end( if (PROFILE_TEXTURE_TIMED()) { profile_timesection_end_now(&profile_globals.current_frame.texture); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.texture); +#endif } return; @@ -1220,6 +1315,9 @@ void profile_idle_start( void) { profile_timesection_begin_now(&profile_globals.current_frame.idle); +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_timer_names.idle); +#endif return; } @@ -1228,6 +1326,9 @@ void profile_idle_end( void) { profile_timesection_end_now(&profile_globals.current_frame.idle); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.idle); +#endif return; } @@ -1249,6 +1350,9 @@ void profile_enter_private( QUERY_TIMEBASE(timebase); section->entry_timebase = timebase; section->frame_call_count++; +#ifdef HALO_PROFILE + profile_trace_begin(profile_trace_section_names[section->section_index]); +#endif return; } @@ -1271,6 +1375,9 @@ void profile_exit_private( QUERY_TIMEBASE(timebase); section->frame_elapsed_timebase += timebase-section->entry_timebase; section->stack_depth = NONE; +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_section_names[section->section_index]); +#endif } else { @@ -1476,6 +1583,9 @@ void profile_frame_end( short frame_index; profile_timesection_end_now(&profile_globals.current_frame.frame); +#ifdef HALO_PROFILE + profile_trace_end(profile_trace_timer_names.frame); +#endif match_assert("c:\\halo\\SOURCE\\cseries\\profile.c", 448, (profile_globals.current_frame.game_tick_count >= 0) && (profile_globals.current_frame.game_tick_count <= MAXIMUM_GAME_TICKS_PER_FRAME)); @@ -1740,6 +1850,9 @@ void find_profile_section( section->section_index = profile_globals.section_count; profile_globals.section_count++; profile_globals.sections[section->section_index] = section; +#ifdef HALO_PROFILE + profile_trace_section_names[section->section_index] = (short)profile_trace_name(section->name); +#endif csmemset(section->frame_elapsed_timebase_history, 0, sizeof(section->frame_elapsed_timebase_history)); csmemset(section->frame_call_count_history, 0, sizeof(section->frame_call_count_history)); diff --git a/source/cseries/profile_sections.h b/source/cseries/profile_sections.h new file mode 100644 index 00000000..627017c7 --- /dev/null +++ b/source/cseries/profile_sections.h @@ -0,0 +1,31 @@ +/* +PROFILE_SECTIONS.H + +Wrap game CPU sections without changing normal builds. +*/ + +#ifndef __PROFILE_SECTIONS_H +#define __PROFILE_SECTIONS_H + +#ifdef HALO_PROFILE + +#include "cseries/profile.h" + +/* these macros leave no tokens in a normal build: call sites have no trailing +semicolon. a call site may be an unbraced if-branch: in a normal build +profile_scope is the statement alone. */ +#define PROFILE_SECTION(variable, name) static struct profile_section variable = { name, NONE, TRUE }; +#define profile_scope_enter(variable) profile_enter(variable) +#define profile_scope_exit(variable) profile_exit(variable) +#define profile_scope(variable, statement) { profile_enter(variable) statement profile_exit(variable) } + +#else + +#define PROFILE_SECTION(variable, name) +#define profile_scope_enter(variable) +#define profile_scope_exit(variable) +#define profile_scope(variable, statement) statement + +#endif + +#endif diff --git a/source/game/game.c b/source/game/game.c index 83742035..7c6cfdc3 100644 --- a/source/game/game.c +++ b/source/game/game.c @@ -182,6 +182,10 @@ struct game_options; #include "units/units.h" #include "units/vehicles.h" #include "network_coop.h" /* port: port/linux/game/network_coop.c */ +#ifdef HALO_PROFILE +#include "profile_console.h" +#endif +#include "cseries/profile_sections.h" /* network_game_globals.c's */ boolean network_game_distributed_client(void); @@ -248,6 +252,25 @@ char const *global_game_difficulty_level_names[NUMBER_OF_GAME_DIFFICULTY_LEVELS] }; static struct profile_section game_update_section = {"game_update", NONE, TRUE}; +/* port: game_tick's steps, timed in the profiling build */ +PROFILE_SECTION(game_tick_cheats_enforce_section, "game_tick.cheats_enforce") +PROFILE_SECTION(game_tick_remove_quitting_players_section, "game_tick.remove_quitting_players") +PROFILE_SECTION(game_tick_allegiance_section, "game_tick.allegiance") +PROFILE_SECTION(game_tick_units_section, "game_tick.units") +PROFILE_SECTION(game_tick_ai_section, "game_tick.ai") +PROFILE_SECTION(game_tick_actors_drive_section, "game_tick.actors_drive") +PROFILE_SECTION(game_tick_players_before_section, "game_tick.players_before") +PROFILE_SECTION(game_tick_effects_section, "game_tick.effects") +PROFILE_SECTION(game_tick_antennas_section, "game_tick.antennas") +PROFILE_SECTION(game_tick_first_person_section, "game_tick.first_person") +PROFILE_SECTION(game_tick_game_engine_section, "game_tick.game_engine") +PROFILE_SECTION(game_tick_editor_section, "game_tick.editor") +PROFILE_SECTION(game_tick_hs_section, "game_tick.hs") +PROFILE_SECTION(game_tick_recorded_animations_section, "game_tick.recorded_animations") +PROFILE_SECTION(game_tick_objects_section, "game_tick.objects") +PROFILE_SECTION(game_tick_players_after_section, "game_tick.players_after") +PROFILE_SECTION(game_tick_hud_section, "game_tick.hud") +PROFILE_SECTION(game_tick_player_effect_section, "game_tick.player_effect") /* ---------- public code */ @@ -328,45 +351,46 @@ void game_tick( /* port: a client of another's game, the host's rules (its own cheats and game speed, set before it joined too, put back) */ - cheats_network_client_enforce(); - remove_quitting_players_from_game(); - game_allegiance_update(); - units_update(); + profile_scope(game_tick_cheats_enforce_section, cheats_network_client_enforce();) + profile_scope(game_tick_remove_quitting_players_section, remove_quitting_players_from_game();) + profile_scope(game_tick_allegiance_section, game_allegiance_update();) + profile_scope(game_tick_units_section, units_update();) /* (the host's actors drive the host's units, which a client of the distributed netcode has from the host: its own would fight the host's positions, and could place objects of their own) */ if (!network_game_distributed_client()) - ai_update(); + profile_scope(game_tick_ai_section, ai_update();) else - network_actors_drive(); - players_update_before_game(); + profile_scope(game_tick_actors_drive_section, network_actors_drive();) + profile_scope(game_tick_players_before_section, players_update_before_game();) seconds_per_tick = game_globals->players_are_double_speed ? 1.0f / (2 * TICKS_PER_SECOND) : 1.0f / TICKS_PER_SECOND; - effects_update(seconds_per_tick); + profile_scope(game_tick_effects_section, effects_update(seconds_per_tick);) /* An antenna's chain is a simulation of the Xbox's own step, an update a tick: stepped a frame at a time, its springs, its carry and its points' physics act against the frames' own movement of it, and a vehicle at speed swings it far wider than a tick's step does. The frames between the ticks are drawn from what each tick leaves (antenna.c). */ - antennas_update(seconds_per_tick); - lock_global_random_seed(); - rumble_update(); - first_person_weapons_update(); - unlock_global_random_seed(); - game_engine_update(); - editor_update(); + profile_scope(game_tick_antennas_section, antennas_update(seconds_per_tick);) + profile_scope(game_tick_first_person_section, + lock_global_random_seed(); + rumble_update(); + first_person_weapons_update(); + unlock_global_random_seed();) + profile_scope(game_tick_game_engine_section, game_engine_update();) + profile_scope(game_tick_editor_section, editor_update();) /* port: in network co-op only the host runs the scripts. A client running them would place the map's actors and objects a second time and make decisions that belong to the host. */ if (!(network_game_distributed_client() && network_coop_active())) - hs_update(); - recorded_animations_update(); - objects_update(); - players_update_after_game(); - hud_update(); - player_effect_update(); + profile_scope(game_tick_hs_section, hs_update();) + profile_scope(game_tick_recorded_animations_section, recorded_animations_update();) + profile_scope(game_tick_objects_section, objects_update();) + profile_scope(game_tick_players_after_section, players_update_after_game();) + profile_scope(game_tick_hud_section, hud_update();) + profile_scope(game_tick_player_effect_section, player_effect_update();) /* port: and at its end, before the frame draws the lights */ game_state_check_data_arrays(); lights_port_recover(); @@ -584,6 +608,11 @@ boolean game_is_cooperative( boolean game_load( struct game_options *options) { +#ifdef HALO_PROFILE + /* (every map load passes here: main_new_map's and a network game's, + network_game_manager.c) */ + profile_console_map_loaded(options->map_name); +#endif match_assert( "c:\\halo\\SOURCE\\game\\game.c", 0x192, diff --git a/source/game/game_time.c b/source/game/game_time.c index 739418be..8e40cc8d 100644 --- a/source/game/game_time.c +++ b/source/game/game_time.c @@ -75,9 +75,15 @@ symbols in this file: #include "networking/network_game_globals.h" #include "networking/network_server_manager.h" #include "saved games/game_state.h" +#include "cseries/profile_sections.h" /* port/linux/game/network_distributed.c's */ void network_distributed_tick(void); +/* port: the tick loop's steps, timed in the profiling build */ +PROFILE_SECTION(game_time_network_distributed_tick_section, "network_distributed_tick") +PROFILE_SECTION(game_time_render_interpolation_tick_section, "render_interpolation_tick") +PROFILE_SECTION(game_time_game_frame_section, "game_frame") + /* ---------- constants */ enum @@ -468,11 +474,11 @@ void game_time_update( for (update_index = 0; update_index < server_updates; update_index++) { game_tick(); - render_interpolation_tick(); + profile_scope(game_time_render_interpolation_tick_section, render_interpolation_tick();) game_time_globals->server_time++; game_time_globals->local_time++; /* the distributed netcode's per-tick state */ - network_distributed_tick(); + profile_scope(game_time_network_distributed_tick_section, network_distributed_tick();) } } @@ -488,7 +494,7 @@ void game_time_update( (port/linux/game/render_interpolation.c). The frames of one tick share the fraction, so what they hang off is drawn where they put it. */ render_interpolation_frame_begin(); - game_frame(game_time_get_speed()*time_delta_sec); + profile_scope(game_time_game_frame_section, game_frame(game_time_get_speed()*time_delta_sec);) render_interpolation_frame_end(); } else diff --git a/source/hs/hs.c b/source/hs/hs.c index e1f6fde6..a3f6f469 100644 --- a/source/hs/hs.c +++ b/source/hs/hs.c @@ -2840,6 +2840,9 @@ symbols in this file: #include "units/units.h" #include "units/vehicles.h" #include "coop_scripts.h" /* port: port/linux/game/coop_scripts.c */ +#ifdef HALO_PROFILE +#include "profile_console.h" +#endif /* ---------- constants */ @@ -15357,6 +15360,12 @@ static boolean hs_compile_and_evaluate_command( char buffer[1024]; char expanded[1024]; +#ifdef HALO_PROFILE + /* port: the profiling build's commands change nothing of the game: a client + may give them, and they are no scripts */ + if (profile_console_command(expression)) + return TRUE; +#endif /* port: the co-op host's bringto, which brings every player to the host (players.c; a client is told it is the host's) */ if (hs_host_player_command(expression, "bringto")) diff --git a/source/main/console.c b/source/main/console.c index 4b8a7103..d67d4e4a 100644 --- a/source/main/console.c +++ b/source/main/console.c @@ -129,7 +129,9 @@ void console_open( { console_globals.input_state.result[0] = '\0'; console_globals.active = terminal_gets_begin(&console_globals.input_state); +#ifndef HALO_PROFILE profile_global_enable = FALSE; +#endif } return; @@ -498,7 +500,12 @@ boolean console_update( { console_globals.input_state.result[0] = '\0'; console_globals.active = terminal_gets_begin(&console_globals.input_state); + /* port: the profiling build: cleared mid-frame, a section already entered + would never exit, and its next enter assert; and opening the console + to type profile_stop would end the recording's timing */ +#ifndef HALO_PROFILE profile_global_enable = FALSE; +#endif } return console_globals.active; diff --git a/source/main/main.c b/source/main/main.c index 31a23036..1f2510a6 100644 --- a/source/main/main.c +++ b/source/main/main.c @@ -380,6 +380,10 @@ symbols in this file: #include "networking/network_game_manager.h" #include "networking/network_server_manager.h" /* port: a co-op game's level won */ #include "network_coop.h" /* port: port/linux/game/network_coop.c */ +#include "cseries/profile_sections.h" +#ifdef HALO_PROFILE +#include "profile_trace.h" +#endif #include "camera/director.h" #include "camera/observer.h" #include "cutscene/cinematics.h" @@ -1440,6 +1444,16 @@ short main_get_window_count( return single_window ? 1 : PIN(local_player_count(), 1, MAXIMUM_WINDOWS); } +#ifdef HALO_PROFILE +/* port: whether the main menu's map is the one loaded (profile_console.c: a +recording of debug.profile_record_when = "game" waits for another) */ +boolean main_menu_is_loaded( + void) +{ + return main_globals.main_menu_scenario_loaded; +} +#endif + static void main_new_map( struct game_options *options) { @@ -2364,6 +2378,9 @@ void main_set_map_name( static void main_exit( void) { +#ifdef HALO_PROFILE + profile_trace_shutdown(); +#endif switch (main_globals.connection) { case _game_connection_network_server: @@ -3311,6 +3328,18 @@ static void main_game_render( return; } +/* port: the main loop's steps, timed in the profiling build */ +PROFILE_SECTION(main_input_section, "input") +PROFILE_SECTION(main_platform_events_section, "platform_events") +PROFILE_SECTION(main_network_start_frame_section, "network_start_frame") +PROFILE_SECTION(main_update_time_section, "main_update_time") +PROFILE_SECTION(main_ui_update_section, "ui_update") +PROFILE_SECTION(main_network_end_frame_section, "network_end_frame") +PROFILE_SECTION(main_game_time_update_section, "game_time_update") +PROFILE_SECTION(main_non_deterministic_update_section, "non_deterministic_update") +PROFILE_SECTION(main_throttle_section, "throttle") +PROFILE_SECTION(main_present_section, "present") + void main_loop( void) { @@ -3424,12 +3453,16 @@ void main_loop( } profile_frame_start(); + profile_scope_enter(main_input_section) input_frame_begin(); input_update(); input_abstraction_update(); + profile_scope_exit(main_input_section) + profile_scope_enter(main_platform_events_section) shell_idle(); event_manager_update(); telnet_console_process(); + profile_scope_exit(main_platform_events_section) if (!shell_application_is_paused()) { @@ -3437,6 +3470,7 @@ void main_loop( /* automated system link tests (port/linux/game/network_test.c) */ network_test_update(main_globals.main_menu_scenario_loaded, main_globals.seconds_elapsed); + profile_scope_enter(main_network_start_frame_section) connection = main_globals.connection; if (connection==_game_connection_network_client) { @@ -3464,12 +3498,16 @@ void main_loop( } else if (connection==_game_connection_film_playback) { + profile_scope_exit(main_network_start_frame_section) break; } + profile_scope_exit(main_network_start_frame_section) - main_update_time(); + profile_scope(main_update_time_section, main_update_time();) + profile_scope_enter(main_ui_update_section) process_ui_widgets(); bink_playback_update(); + profile_scope_exit(main_ui_update_section) if ((!game_in_editor() && (input_key_is_down(_key_end) || input_key_is_down(_key_escape))) || editor_should_exit()) { @@ -3492,13 +3530,16 @@ void main_loop( player_control_update((real)main_globals.halt_time_scale*main_globals.seconds_elapsed); connection = main_globals.connection; + profile_scope_enter(main_network_end_frame_section) if (connection>_game_connection_local && connection<=_game_connection_network_server && !network_game_client_end_frame()) { display_error_when_main_menu_loaded(1); network_game_abort(); } + profile_scope_exit(main_network_end_frame_section) - game_time_update((real)main_globals.halt_time_scale*main_globals.seconds_elapsed); + profile_scope(main_game_time_update_section, + game_time_update((real)main_globals.halt_time_scale*main_globals.seconds_elapsed);) render_frame = main_globals.main_menu_scenario_loaded || (main_globals.halt_time_scale && @@ -3508,11 +3549,13 @@ void main_loop( render_frame = main_globals.main_menu_scenario_loaded || main_globals.halt_time_scale; render_frame &= !game_engine_running() || game_time_get()>=3; + profile_scope_enter(main_non_deterministic_update_section) collision_log_continue_period(1); director_update((real)main_globals.halt_time_scale*main_globals.seconds_elapsed); observer_update((real)main_globals.halt_time_scale*main_globals.seconds_elapsed); collision_log_end_period(); game_engine_update_non_deterministic((real)main_globals.halt_time_scale*main_globals.seconds_elapsed); + profile_scope_exit(main_non_deterministic_update_section) } if (main_globals.saving_map) @@ -3536,11 +3579,11 @@ void main_loop( profile_render_end(); } - main_rasterizer_throttle(); + profile_scope(main_throttle_section, main_rasterizer_throttle();) if (render_frame && !debug_no_drawing) { - main_present_frame(); + profile_scope(main_present_section, main_present_frame();) } } diff --git a/tools/android_build.py b/tools/android_build.py index fcce7c58..e81b8f1e 100644 --- a/tools/android_build.py +++ b/tools/android_build.py @@ -26,7 +26,7 @@ from pathlib import Path from typing import Any, Dict, List, Optional from .linux_build import (LINUX_PROFILE, MINIUPNPC_DEFINES, MINIUPNPC_DIR, MUSL_MATH_DIR, XDK_INCLUDE, - compile_launcher, game_defines_and_includes, game_sources, miniupnpc_sources, + compile_launcher, configuration_defines, game_defines_and_includes, game_sources, miniupnpc_sources, musl_math_sources, pgo_mode, pgo_profile, profile_use_flags, updater_defines, xdk_headers) from .embed_assets import hud_assets_build, hud_configure_inputs @@ -378,7 +378,7 @@ def generate_android_build(n: Writer, sln: Any) -> None: f"-isystem {libc_include}", f"-isystem {arch}", f"-isystem {MUSL_DIR}/arch/generic", f"-isystem {MUSL_DIR}/include", ] - guest_abi = " ".join(GUEST_ABI_FLAGS + (["-DHALO_RELEASE"] if getattr(sln, "port_release", False) else [])) + guest_abi = " ".join(GUEST_ABI_FLAGS + configuration_defines(sln)) guest_code = " ".join(GUEST_CODE_FLAGS) tool_implicit = [Path("tools/android_asm_convert.py"), *generated_headers] # profile-guided optimisation with the Linux build's profile (committed, diff --git a/tools/linux_build.py b/tools/linux_build.py index 5569daec..c40564c1 100644 --- a/tools/linux_build.py +++ b/tools/linux_build.py @@ -151,6 +151,25 @@ def updater_defines(release: bool) -> str: flavor = "release" if release else "debug" return f'-DHALO_BUILD_NUMBER={number} -DHALO_BUILD_FLAVOR=\\"{flavor}\\"' +def configuration_defines(sln: Any) -> List[str]: + """what configure.py's options define for every unit of a native build: + --release (no assertions), --profile (the profiling build's recording, + port/linux/src/profile_trace.c)""" + defines = [] + if getattr(sln, "port_release", False): + defines.append("-DHALO_RELEASE") + if getattr(sln, "port_profile", False): + defines.append("-DHALO_PROFILE") + return defines + + +def check_profile_options(profile: bool, pgo: str) -> None: + """A profiling build is optimised with the committed profiles or none: + trained, a profile would record the profiling code's own paths.""" + if profile and pgo == "train": + raise ValueError("--profile cannot be used with --pgo=train: train profiles with a normal build") + + PLATFORM_FLAGS = [ "-std=gnu11", "-D_GNU_SOURCE", @@ -385,8 +404,8 @@ def generate_linux_build(n: Writer, sln: Any) -> None: # (a debug build checks its stack frames, and stops at the first one # overrun, as it stops at the first failed assertion; a release build # does not, so that an overrun nobody has met cannot end a game) - abi = " ".join(LINUX_ABI_FLAGS + [march_flag(sln)] + (["-DHALO_RELEASE"] if getattr(sln, "port_release", False) - else ["-fstack-protector-strong"])) + abi = " ".join(LINUX_ABI_FLAGS + [march_flag(sln)] + configuration_defines(sln) + + ([] if getattr(sln, "port_release", False) else ["-fstack-protector-strong"])) port_include = PORT_DIR / "include" sdk_flags = f"-idirafter {XDK_INCLUDE}" libs = " ".join(f"-l{lib}" for lib in config.get("libraries", [])) diff --git a/tools/net_report.py b/tools/net_report.py new file mode 100644 index 00000000..5e947a1c --- /dev/null +++ b/tools/net_report.py @@ -0,0 +1,306 @@ +#!/usr/bin/env python3 +"""Summarize CPU profiling recordings. +Usage: python tools/net_report.py RECORDING [RECORDING2 ...] [options].""" + +import argparse +import csv +import json +import re +import sys +from pathlib import Path + +FORMAT = 1 +SUMMARY_LINE_LIMIT = 300 +# (the summary file always uses this, so its length does not depend on --top) +SUMMARY_TOP = 40 +REQUIRED_HEADER = ("part", "last_part", "role", "own_machine", "build", "platform", "map", + "players", "start_utc", "start_s", "duration_s", + "stop_reason") +PER_TICK_PREFIXES = ("game_tick", "network_distributed_tick") + +COLUMNS_GLOSSARY = """\ +scope CPU scope name (a profile section or frame timer); nested names use "." +count times the scope ran in the recording +total_ms summed inclusive time (children included), milliseconds +mean_ms total_ms / count +max_ms longest single run; aggregate sections: largest summed time in one frame +per_frame count / frames recorded +per_tick_ms total_ms / ticks recorded (game_tick.* and network_distributed_tick* only) +frame frame number in the recording +at_s seconds from the start of the recording to that frame +frame_ms that frame's duration +ticks game ticks that frame ran +longest scopes (ms) the frame's three scopes, at any depth, with the most time of their own (children not counted), name and that time""" + + +class ReportError(Exception): + pass + + +# ---------- reading a recording + + +def part_paths(recording): + """the recording's name, its part files by number, and the warnings""" + path = Path(recording) + match = re.match(r"^(.*)\.part(\d+)\.json$", path.name) + base = path.parent / (match.group(1) if match else re.sub(r"\.json$", "", path.name)) + parts = {} + for candidate in base.parent.glob(base.name + ".part*.json"): + number = re.match(r"^.*\.part(\d+)\.json$", candidate.name) + if number and candidate.name.startswith(base.name + ".part"): + parts[int(number.group(1))] = candidate + if not parts: + raise ReportError(f"no parts of {base}") + warnings = [f"part {number} of {base.name} is missing" for number in range(1, max(parts) + 1) + if number not in parts] + return base, [parts[number] for number in sorted(parts)], warnings + + +def read_head(path): + """the header and cpu tables, read before the event array""" + with open(path, "r", encoding="utf-8") as file: + return read_head_stream(file, path) + + +def read_head_stream(file, path): + text = "" + marker = '"traceEvents"' + while marker not in text: + chunk = file.read(65536) + if not chunk: + raise ReportError(f"{path}: has no traceEvents") + text += chunk + text = text.split(marker, 1)[0].rstrip().rstrip(",") + "}" + try: + head = json.loads(text) + except json.JSONDecodeError as error: + raise ReportError(f"{path}: not a recording part ({error})") from None + if not isinstance(head, dict): + raise ReportError(f"{path}: not a recording part") + for key in ("halo", "cpu_summary"): + if not isinstance(head.get(key), dict): + raise ReportError(f'{path}: has no "{key}"') + _validate_head_part(head, path) + return [head] + + +def _validate_head_part(head, path): + where = str(path) + for key in ("halo", "cpu_summary"): + if not isinstance(head.get(key), dict): + raise ReportError(f'{where}: has no "{key}"') + header = head["halo"].get("header") + if not isinstance(header, dict): + raise ReportError(f'{where}: has no "header" in "halo"') + for key in REQUIRED_HEADER: + if key not in header: + raise ReportError(f'{where}: the header has no "{key}"') + + +def table_dicts(table): + columns = table["columns"] + return [dict(zip(columns, row)) for row in table["rows"]] + + +class Recording: + """a recording's parts with their CPU summaries merged""" + + def __init__(self, recording): + self.base, paths, self.warnings = part_paths(recording) + heads = [head for part in paths for head in read_head(part)] + self.name = self.base.name + self.headers = [head["halo"]["header"] for head in heads] + self.parts = [header["part"] for header in self.headers] + self.complete = any(header["last_part"] for header in self.headers) + if not self.complete: + self.warnings.append(f"{self.name} has no last part: the recording is incomplete") + self.header = self.headers[0] + self.cpu = self.merge_cpu([head["cpu_summary"] for head in heads]) + + @staticmethod + def merge_cpu(summaries): + names = {} + frames = sum(summary["frames"] for summary in summaries) + ticks = sum(summary["ticks"] for summary in summaries) + worst = [] + for summary in summaries: + for row in table_dicts(summary): + totals = names.setdefault(row["name"], {"count": 0, "total_ms": 0.0, "max_ms": 0.0}) + totals["count"] += row["count"] + totals["total_ms"] += row["total_ms"] + totals["max_ms"] = max(totals["max_ms"], row["max_ms"]) + worst.extend(table_dicts(summary["worst_frames"])) + for name, totals in names.items(): + totals["mean_ms"] = totals["total_ms"] / totals["count"] if totals["count"] else 0.0 + totals["per_frame"] = totals["count"] / frames if frames else 0.0 + totals["per_tick_ms"] = (totals["total_ms"] / ticks if ticks and name.startswith(PER_TICK_PREFIXES) + else None) + worst.sort(key=lambda row: -row["frame_ms"]) + return {"frames": frames, "ticks": ticks, "names": names, "worst": worst[:10]} + + def select(self, start=None, end=None): + """Elapsed seconds from the recorded part headers, clipped to a window.""" + seconds = 0.0 + for header in self.headers: + begin = header["start_s"] + finish = begin + header["duration_s"] + seconds += max(0.0, min(finish, end if end is not None else finish) - + max(begin, start if start is not None else begin)) + return seconds + + +# ---------- the tables + + +def cpu_table(recording): + rows = [[name, totals["count"], totals["total_ms"], totals["mean_ms"], totals["max_ms"], totals["per_frame"], + totals["per_tick_ms"]] for name, totals in recording.cpu["names"].items()] + rows.sort(key=lambda row: (-row[2], row[0])) + return ["scope", "count", "total_ms", "mean_ms", "max_ms", "per_frame", "per_tick_ms"], rows + + +def worst_frame_table(recording): + rows = [[row["frame"], row["at_s"], row["frame_ms"], row["ticks"], + ", ".join(f"{name} {ms:.1f}" for name, ms in row["longest"])] for row in recording.cpu["worst"]] + return ["frame", "at_s", "frame_ms", "ticks", "longest scopes (ms)"], rows + + +# ---------- text + + +NUMBER_FORMATS = { + "count": "{:.0f}", "total_ms": "{:.1f}", "mean_ms": "{:.3f}", "max_ms": "{:.3f}", "per_frame": "{:.2f}", + "per_tick_ms": "{:.3f}", "frame": "{:.0f}", "at_s": "{:.2f}", "frame_ms": "{:.2f}", "ticks": "{:.0f}", +} +TEXT_WIDTH = {"scope": 40, "longest scopes (ms)": 72} + + +def cell(column, value): + if value is None: + return "-" + if isinstance(value, (int, float)) and not isinstance(value, bool) and column in NUMBER_FORMATS: + return NUMBER_FORMATS[column].format(value) + text = str(value) + width = TEXT_WIDTH.get(column) + if width and len(text) > width: + text = text[:width - 1] + "~" + return text + + +def format_table(columns, rows, limit=None): + """aligned lines: names left, numbers right; past the limit a line of + how many more""" + shown = rows if limit is None else rows[:limit] + if not shown: + return ["(none)"] + cells = [[cell(column, value) for column, value in zip(columns, row)] for row in shown] + numeric = [column in NUMBER_FORMATS for column in columns] + widths = [max([len(column)] + [len(line[index]) for line in cells]) for index, column in enumerate(columns)] + + def line(values): + parts = [value.rjust(width) if is_number else value.ljust(width) + for value, width, is_number in zip(values, widths, numeric)] + return " ".join(parts).rstrip() + + lines = [line(columns)] + [line(values) for values in cells] + if limit is not None and len(rows) > limit: + lines.append(f"... {len(rows) - limit} more rows (net_report.py --top N)") + return lines + + +def problems(recording): + found = list(recording.warnings) + counters = (("unbalanced_scopes", "unbalanced scopes"), ("deep_scopes", "deep scopes"), + ("foreign_scopes", "foreign scopes"), ("dropped_scopes", "dropped scopes")) + for key, label in counters: + total = sum(header.get(key, 0) for header in recording.headers) + if total: + found.append(f"{label} {total}") + wait = sum(header.get("writer_wait_ms", 0.0) for header in recording.headers[-1:]) + if wait: + found.append(f"writer waited {wait:.0f} ms") + return found + + +def summary_lines(recording, start, end, top): + seconds = recording.select(start, end) + windowed = start is not None or end is not None + whole = recording.select() + header, last = recording.header, recording.headers[-1] + parts = f"parts {min(recording.parts)}-{max(recording.parts)}" if len(recording.parts) > 1 else "part 1" + state = "complete" if recording.complete and not any( + "missing" in warning for warning in recording.warnings) else "incomplete" + found = problems(recording) + own = header["own_machine"] if header["own_machine"] >= 0 else "-" + lines = [ + f"# halo profile summary, format {FORMAT}", + f"# recording: {recording.name}, {parts} ({state})", + f"# build: {header['build']}, platform: {header['platform']}, role: {header['role']}, own_machine: {own}", + f"# map: {header['map']}, players: {header['players']} at start, " + f"{max(item.get('players_most', item['players']) for item in recording.headers)} most", + f"# recorded: {header['start_utc']} UTC, {whole:.1f} s, {recording.cpu['ticks']} ticks, " + f"{recording.cpu['frames']} frames, stopped: {last['stop_reason'] or '-'}", + *([f"# window: {seconds:.1f} s selected (seconds {start if start is not None else 0:g} to " + f"{f'{end:g}' if end is not None else 'end'}); the cpu tables, ticks and frames cover the whole recording"] + if windowed else []), + f"# problems: {'; '.join(found) if found else 'none'}", + "# units: ms = milliseconds", "", "## columns", + ] + note = ", whole recording" if windowed else "" + sections = [(f"cpu scopes (top {min(top, 40)} by total_ms{note})", cpu_table(recording), min(top, 40)), + (f"worst frames (10{note})", worst_frame_table(recording), 10)] + printed = {column for _, (columns, rows), _ in sections if rows for column in columns} + lines.extend(line for line in COLUMNS_GLOSSARY.splitlines() if re.split(r"\s{2,}", line, maxsplit=1)[0] in printed) + for title, table, limit in sections: + lines.extend(["", f"## {title}", *format_table(*table, limit)]) + return lines + + +def write_csv(recording, directory): + directory.mkdir(parents=True, exist_ok=True) + for name, (columns, rows) in {"cpu": cpu_table(recording), "worst_frames": worst_frame_table(recording)}.items(): + with open(directory / f"{recording.name}.{name}.csv", "w", newline="", encoding="ascii", errors="replace") as file: + writer = csv.writer(file) + writer.writerow(columns) + writer.writerows([[NUMBER_FORMATS[column].format(value) + if column in NUMBER_FORMATS and isinstance(value, (int, float)) else + ("-" if value is None else value) for column, value in zip(columns, row)] for row in rows]) + + +def main(arguments=None): + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0]) + parser.add_argument("recordings", nargs="+", metavar="RECORDING") + parser.add_argument("--from", dest="start", type=float, help="from this second of the recording") + parser.add_argument("--to", dest="end", type=float, help="to this second") + parser.add_argument("--top", type=int, default=40, help="CPU rows (default 40)") + parser.add_argument("--csv", type=Path, metavar="DIR", help="every table as CSV in DIR") + parser.add_argument("--no-summary", action="store_true", help="do not write .summary.txt") + options = parser.parse_args(arguments) + try: + recordings = [Recording(name) for name in options.recordings] + except (ReportError, OSError) as error: + print(f"net_report: {error}", file=sys.stderr) + return 1 + for recording in recordings: + try: + lines = summary_lines(recording, options.start, options.end, options.top) + file_lines = lines if options.top == SUMMARY_TOP else summary_lines( + recording, options.start, options.end, SUMMARY_TOP) + except (KeyError, TypeError, IndexError, ValueError) as error: + print(f"net_report: {recording.name}: a table is not as the writer wrote it ({error!r})", file=sys.stderr) + return 1 + for warning in recording.warnings: + print(f"warning: {warning}", file=sys.stderr) + print("\n".join(lines)) + print() + if not options.no_summary: + path = recording.base.parent / f"{recording.name}.summary.txt" + path.write_text("\n".join(file_lines) + "\n", encoding="ascii", errors="replace") + if options.csv: + write_csv(recording, options.csv) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/profile_check.c b/tools/profile_check.c new file mode 100644 index 00000000..27ed1538 --- /dev/null +++ b/tools/profile_check.c @@ -0,0 +1,1059 @@ +/* +PROFILE_CHECK.C + +Exercise the CPU recorder and writer with standalone fakes. +*/ + +#include "profile_part.h" +#include "profile_console_gametype.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +/* ---------- fakes */ + +static int failures; +static int session_sample_calls; +static unsigned long long fake_now = 1000000000ULL; +static pthread_mutex_t fake_track_lock = PTHREAD_MUTEX_INITIALIZER; +static pthread_mutex_t fake_allocator_lock = PTHREAD_MUTEX_INITIALIZER; +static long allocations_outstanding; +static long allocations_made; +static int allocations_refused; +/* allocations that succeed before the rest are refused (-1: no such limit) */ +static int allocations_allowed = -1; +static int fake_ready; +static const char *fake_role = "host"; +static long fake_players = 2; +static long fake_own_machine = -1; +static const char *fake_map = "levels\\a30\\a30"; +static const char *fake_map_name = "a30"; +static const char *fake_folder = "."; +static char last_notice[128]; +static char last_log[600]; +static int name_aggregate_child; + +static void check(int good, const char *what) +{ + if (!good) + { + failures++; + printf("FAIL: %s\n", what); + } +} + +static void gametype_checks(void) +{ + static const char *const expected[] = { "none", "ctf", "slayer", "oddball", "king", "race" }; + long engine; + for (engine = 0; engine <= 5; engine++) + check(strcmp(profile_console_engine_gametype(1, engine), expected[engine]) == 0, + "engine index maps to its engine gametype"); + check(strcmp(profile_console_engine_gametype(0, 2), "campaign") == 0, + "campaign does not reuse a stale slayer variant"); + check(strcmp(profile_console_engine_gametype(1, 6), "none") == 0 && + strcmp(profile_console_engine_gametype(1, 7), "none") == 0, "an engine past race is none"); + check(strcmp(profile_console_scenario_map("levels\\b30\\b30", "ui"), "levels\\b30\\b30") == 0, + "the pending scenario takes precedence over the previous map"); +} + +static unsigned long long fake_clock(void) +{ + return __atomic_load_n(&fake_now, __ATOMIC_RELAXED); +} + +static void advance(unsigned long long nanoseconds) +{ + __atomic_fetch_add(&fake_now, nanoseconds, __ATOMIC_RELAXED); +} + +static void fake_lock(void) +{ + pthread_mutex_lock(&fake_track_lock); +} + +static void fake_unlock(void) +{ + pthread_mutex_unlock(&fake_track_lock); +} + +static void *fake_allocate(unsigned long size) +{ + void *block; + + pthread_mutex_lock(&fake_allocator_lock); + block = allocations_refused || allocations_allowed == 0 ? NULL : malloc(size); + if (allocations_allowed > 0) + allocations_allowed--; + if (block) + { + allocations_outstanding++; + allocations_made++; + } + pthread_mutex_unlock(&fake_allocator_lock); + return block; +} + +static void fake_release(void *block) +{ + if (!block) + return; + pthread_mutex_lock(&fake_allocator_lock); + allocations_outstanding--; + pthread_mutex_unlock(&fake_allocator_lock); + free(block); +} + +static long outstanding(void) +{ + long count; + + pthread_mutex_lock(&fake_allocator_lock); + count = allocations_outstanding; + pthread_mutex_unlock(&fake_allocator_lock); + return count; +} + +static void quiet_log(const char *text) +{ + if (strstr(text, "cannot write")) + snprintf(last_log, sizeof(last_log), "%s", text); +} + +static void fake_notify(const char *text) +{ + snprintf(last_notice, sizeof(last_notice), "%s", text); +} + +static int fake_ready_test(void) +{ + return fake_ready; +} + +static void fake_session(struct profile_trace_session *session) +{ + memset(session, 0, sizeof(*session)); + snprintf(session->folder, sizeof(session->folder), "%s", fake_folder); + strcpy(session->build, "check"); + strncpy(session->role, fake_role, sizeof(session->role) - 1); + session->own_machine = fake_own_machine; + strncpy(session->map, fake_map, sizeof(session->map) - 1); + strncpy(session->map_name, fake_map_name, sizeof(session->map_name) - 1); + strcpy(session->gametype, "campaign"); + session->players = fake_players; + session->players_most = fake_players; +} + +static void fake_session_sample(struct profile_trace_session *session) +{ + session_sample_calls++; + fake_session(session); +} + +/* ---------- the fake writer: what each part held */ + +enum +{ + MAXIMUM_PARTS = 64, +}; + +static struct +{ + pthread_mutex_t lock; + int parts; + int finished; + unsigned long counts[MAXIMUM_PROFILE_TRACE_NAMES]; + unsigned long counter_records; + unsigned long long aggregate_time[MAXIMUM_PROFILE_TRACE_NAMES]; + unsigned long aggregate_count[MAXIMUM_PROFILE_TRACE_NAMES]; + long first_frame[MAXIMUM_PARTS]; + long frames[MAXIMUM_PARTS]; + unsigned long long start_ns[MAXIMUM_PARTS]; + unsigned long long end_ns[MAXIMUM_PARTS]; + int last[MAXIMUM_PARTS]; + int stop_reason[MAXIMUM_PARTS]; + char map_name[MAXIMUM_PARTS][64]; + double writer_wait_ms; + unsigned long unbalanced; + unsigned long deep; + unsigned long foreign; + unsigned long dropped; + int records_in_span; + int aggregate_child_depth; + int delay_milliseconds; +} written = { .lock = PTHREAD_MUTEX_INITIALIZER }; + +static void *fake_writer(void *unused) +{ + (void)unused; + for (;;) + { + struct profile_part *part = profile_trace_writer_next(); + int last = part->last; + unsigned long index; + int track; + + /* (a slow first part: the game thread's wait for it is on the fake + clock too) */ + if (written.delay_milliseconds && part->number == 1) + { + usleep((useconds_t)written.delay_milliseconds * 1000); + advance((unsigned long long)written.delay_milliseconds * 1000000ULL); + } + pthread_mutex_lock(&written.lock); + if (written.parts < MAXIMUM_PARTS) + { + written.first_frame[written.parts] = part->first_frame; + written.frames[written.parts] = part->frames; + written.start_ns[written.parts] = part->start_ns; + written.end_ns[written.parts] = part->end_ns; + written.last[written.parts] = part->last; + written.stop_reason[written.parts] = part->stop_reason; + strcpy(written.map_name[written.parts], part->session.map_name); + } + written.parts++; + written.writer_wait_ms = part->writer_wait_ms; + written.unbalanced += part->unbalanced_scopes; + written.deep += part->deep_scopes; + written.foreign += part->foreign_scopes; + written.dropped += part->dropped_scopes; + for (track = 0; track < NUMBER_OF_PROFILE_TRACKS; track++) + { + for (index = 0; index < part->record_counts[track]; index++) + { + const struct profile_trace_record *record = &part->records[track][index]; + + if (record->depth < MAXIMUM_PROFILE_TRACE_DEPTH) + { + written.counts[record->name]++; + if (record->name == name_aggregate_child) + written.aggregate_child_depth = record->depth; + /* (a scope that began before the part, in the p2p pass a + cut came in, is in the part it ended in) */ + if (record->start + record->duration > part->end_ns) + written.records_in_span = 0; + } + else + { + written.counter_records++; + if (record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_TIME) + written.aggregate_time[record->name] += record->duration; + else if (record->depth == PROFILE_TRACE_DEPTH_AGGREGATE_COUNT) + written.aggregate_count[record->name] += record->duration; + } + } + } + pthread_mutex_unlock(&written.lock); + if (last) + { + pthread_mutex_lock(&written.lock); + written.finished++; + pthread_mutex_unlock(&written.lock); + } + /* Publish the fake writer's last observation before done makes the + recorder idle; finish() may read the observations as soon as it does. */ + profile_trace_writer_done(part); + if (last) + break; + } + return NULL; +} + +static int fake_writer_start(void) +{ + pthread_t thread; + + return pthread_create(&thread, NULL, fake_writer, NULL) == 0 && pthread_detach(thread) == 0; +} + +static void forget_written(void) +{ + pthread_mutex_lock(&written.lock); + written.parts = 0; + written.finished = 0; + memset(written.counts, 0, sizeof(written.counts)); + written.counter_records = 0; + written.unbalanced = written.deep = written.foreign = written.dropped = 0; + written.records_in_span = 1; + pthread_mutex_unlock(&written.lock); +} + +/* whether the writer has finished a recording, read through its lock */ +static int writer_finished(void) +{ + int finished; + + pthread_mutex_lock(&written.lock); + finished = written.finished; + pthread_mutex_unlock(&written.lock); + return finished; +} + +/* frame boundaries until the recording is written and the state idle */ +static void finish(void) +{ + struct profile_trace_status status; + int frames; + + for (frames = 0; frames < 100000; frames++) + { + profile_trace_frame_boundary(); + profile_trace_status(&status); + if (status.state == _profile_trace_idle || status.state == _profile_trace_armed) + { + /* (what the writer noted, seen through its lock) */ + pthread_mutex_lock(&written.lock); + pthread_mutex_unlock(&written.lock); + return; + } + usleep(100); + } + check(0, "the recording finishes"); +} + +/* ---------- checks */ + +static int name_frame, name_tick, name_a, name_b, name_c, name_texture, name_pass, name_inner_aggregate; + +static void frame(int scopes) +{ + int index; + + profile_trace_frame_boundary(); + profile_trace_begin(name_frame); + for (index = 0; index < scopes; index++) + { + profile_trace_begin(name_a); + advance(1000); + profile_trace_begin(name_b); + advance(500); + profile_trace_end(name_b); + profile_trace_end(name_a); + } + advance(1000); + profile_trace_end(name_frame); +} + +static void scope_checks(void) +{ + struct profile_trace_status status; + int index; + + forget_written(); + check(profile_trace_request_start(0.0, _profile_trace_when_now, 4) == _profile_trace_answer_armed, + "profile_record arms"); + profile_trace_status(&status); + check(status.state == _profile_trace_armed, "armed until the next frame boundary"); + check(strncmp(status.name, "profile_", 8) == 0 && strstr(status.name, "_host"), "named when asked for"); + check(!profile_trace_recording(), "not recording before the boundary"); + frame(3); + check(profile_trace_recording(), "recording from the boundary"); + /* the first map load after launch (the main menu) does not stop it */ + profile_trace_map_loaded(); + profile_trace_frame_boundary(); + check(profile_trace_recording(), "the first map load does not stop a recording"); + check(profile_trace_request_start(0.0, _profile_trace_when_now, 4) == _profile_trace_answer_already_recording, + "a second profile_record is refused"); + + /* nesting deeper than the stack: not recorded, counted, and the rest + still balances */ + profile_trace_frame_boundary(); + for (index = 0; index < MAXIMUM_PROFILE_TRACE_DEPTH + 3; index++) + profile_trace_begin(name_c); + for (index = 0; index < MAXIMUM_PROFILE_TRACE_DEPTH + 3; index++) + profile_trace_end(name_c); + /* an end that is not the top's, and one with nothing open */ + profile_trace_begin(name_a); + profile_trace_end(name_b); + profile_trace_end(name_a); + profile_trace_end(name_b); + /* aggregate scopes: summed for the frame, no records */ + profile_trace_begin(name_texture); + profile_trace_begin(name_inner_aggregate); + advance(500); + profile_trace_begin(name_aggregate_child); + advance(1000); + profile_trace_end(name_aggregate_child); + profile_trace_end(name_inner_aggregate); + advance(500); + profile_trace_end(name_texture); + for (index = 0; index < 5; index++) + { + profile_trace_begin(name_texture); + advance(2000); + profile_trace_end(name_texture); + } + /* a scope left open is dropped at the boundary, and counted */ + profile_trace_begin(name_a); + frame(1); + check(profile_trace_request_stop() == _profile_trace_answer_stopping, "profile_stop stops"); + check(profile_trace_recording(), "a stop applies at the next boundary"); + profile_trace_frame_boundary(); + check(!profile_trace_recording(), "stopped at the boundary"); + check(profile_trace_request_start(0.0, _profile_trace_when_now, 4) == _profile_trace_answer_still_writing || + writer_finished(), "profile_record while writing is refused"); + finish(); + check(written.finished == 1 && written.parts == 1, "one part written"); + check(written.counts[name_frame] == 2, "two frames recorded"); + check(written.counts[name_a] == 5 && written.counts[name_b] == 4, "every scope recorded once"); + check(written.counts[name_c] == MAXIMUM_PROFILE_TRACE_DEPTH, "scopes within the stack recorded"); + check(written.deep == 3, "scopes past the stack counted"); + check(written.unbalanced == 3, "unbalanced ends and the open scope counted"); + check(written.counts[name_texture] == 0 && written.counter_records >= 2, "aggregate names give counters"); + check(written.aggregate_child_depth == 0, "ordinary scopes inside an aggregate keep visible depth"); + check(written.aggregate_count[name_texture] == 6 && written.aggregate_time[name_texture] == 12000, + "outer aggregate totals include calls nested with another aggregate"); + check(written.aggregate_count[name_inner_aggregate] == 1 && written.aggregate_time[name_inner_aggregate] == 1500, + "nested aggregate keeps its own cpu summary count and time"); + check(written.counts[name_aggregate_child] == 1, "ordinary nested scope contributes one cpu summary count"); + check(written.stop_reason[0] == _profile_trace_stop_command, "stopped by the command"); + check(outstanding() == 0, "both arenas freed after the recording"); +} + +static void state_checks(void) +{ + struct profile_trace_status status; + + /* game: armed until a game is in progress, stopped by a map load, then + armed again */ + forget_written(); + fake_ready = 0; + fake_map = ""; + fake_map_name = ""; + check(profile_trace_request_start(0.0, _profile_trace_when_game, 4) == _profile_trace_answer_armed, "armed for a game"); + frame(1); + frame(1); + profile_trace_status(&status); + check(status.state == _profile_trace_armed, "waits for a game"); + fake_ready = 1; + frame(1); + check(profile_trace_recording(), "records once a game is in progress"); + frame(1); + fake_map = "levels\\next\\next"; + fake_map_name = "next"; + profile_trace_map_loaded(); + frame(1); + check(!profile_trace_recording(), "a map load stops it"); + finish(); + fake_map = "levels\\a30\\a30"; + fake_map_name = "a30"; + profile_trace_status(&status); + check(status.state == _profile_trace_armed, "armed again for the next game"); + check(written.stop_reason[0] == _profile_trace_stop_map_load, "stopped by the map load"); + check(strcmp(written.map_name[0], "next") != 0, "the map that stops a recording is not sampled into it"); + frame(1); + check(profile_trace_recording(), "the next game is recorded"); + check(profile_trace_request_stop() == _profile_trace_answer_stopping, "stopped by hand"); + frame(1); + finish(); + profile_trace_status(&status); + check(status.state == _profile_trace_idle, "a stop by hand does not arm again"); + check(outstanding() == 0, "nothing left allocated"); + + /* the seconds of profile_record */ + forget_written(); + profile_trace_request_start(0.5, _profile_trace_when_now, 4); + frame(1); + advance(400000000ULL); + frame(1); + check(profile_trace_recording(), "still recording before its seconds"); + advance(200000000ULL); + frame(1); + check(!profile_trace_recording(), "stopped after its seconds"); + finish(); + check(written.stop_reason[0] == _profile_trace_stop_seconds, "stopped by its seconds"); + + /* no memory: not recording, said so, nothing kept */ + allocations_refused = 1; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frame(1); + allocations_refused = 0; + profile_trace_status(&status); + check(status.state == _profile_trace_idle && strstr(last_notice, "no memory for 4 MB"), "no memory is reported"); + check(outstanding() == 0, "a failed allocation keeps nothing"); +} + +static volatile int p2p_running; +static unsigned long p2p_recorded; + +static void *p2p_thread(void *unused) +{ + (void)unused; + profile_trace_thread_register(_profile_track_p2p); + while (__atomic_load_n(&p2p_running, __ATOMIC_RELAXED)) + { + fake_lock(); + if (profile_trace_recording()) + p2p_recorded++; + profile_trace_begin(name_pass); + profile_trace_end(name_pass); + fake_unlock(); + /* (a pass every 50 microseconds: the p2p region holds an eighth of + the scopes, as the game's p2p thread has far fewer) */ + usleep(50); + } + return NULL; +} + +/* what profile_stop answers while a recording is only armed: a game is waited for +only by "game" mode, which stop ends too */ +static void stop_answer_checks(void) +{ + struct profile_trace_status status; + + check(profile_trace_request_start(0.0, _profile_trace_when_now, 4) == _profile_trace_answer_armed, "armed for the next frame"); + check(profile_trace_request_stop() == _profile_trace_answer_not_recording, + "stopped before it began, a recording armed for the next frame was waiting for no game"); + profile_trace_status(&status); + check(status.state == _profile_trace_idle, "stopped while armed, it does not start"); + check(profile_trace_request_start(0.0, _profile_trace_when_game, 4) == _profile_trace_answer_armed, "armed for a game"); + check(profile_trace_request_stop() == _profile_trace_answer_disarmed, "a recording armed for a game is not waited for any more"); + profile_trace_status(&status); + check(status.state == _profile_trace_idle, "stopped while armed for a game, it does not start"); +} + +static void part_checks(void) +{ + pthread_t thread; + unsigned long frames_recorded = 0; + int frame_index, part; + int continuous = 1; + + forget_written(); + p2p_recorded = 0; + p2p_running = 1; + pthread_create(&thread, NULL, p2p_thread, NULL); + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + /* (4 MB, CPU-only: about 114 000 game records a part) */ + for (frame_index = 0; frame_index < 3000; frame_index++) + { + frame(50); + if (profile_trace_recording()) + frames_recorded++; + if (frame_index % 30 == 0) + profile_trace_tick(); + advance(1000000); + } + profile_trace_request_stop(); + profile_trace_frame_boundary(); + __atomic_store_n(&p2p_running, 0, __ATOMIC_RELAXED); + pthread_join(thread, NULL); + finish(); + fake_role = "host"; + fake_players = 2; + fake_own_machine = -1; + check(written.parts >= 3, "a long recording is cut into parts"); + check(written.counts[name_frame] == frames_recorded, "every frame in exactly one part"); + check(written.counts[name_a] == frames_recorded * 50, "every scope in exactly one part"); + check(written.counts[name_pass] == p2p_recorded, "every recorded p2p pass in exactly one part"); + check(written.dropped == 0, "nothing dropped"); + for (part = 1; part < written.parts && part < MAXIMUM_PARTS; part++) + { + continuous &= written.first_frame[part] == written.first_frame[part - 1] + written.frames[part - 1]; + continuous &= written.start_ns[part] == written.end_ns[part - 1]; + continuous &= !written.last[part - 1]; + } + check(continuous, "frames and time continue across parts"); + check(written.last[written.parts - 1], "only the last part is the last"); + check(written.records_in_span, "each record within its part"); + check(outstanding() == 0, "both arenas freed after a long recording"); + + /* a cut while the writer holds the other arena waits for it */ + forget_written(); + written.delay_milliseconds = 1000; + p2p_recorded = 0; + p2p_running = 1; + pthread_create(&thread, NULL, p2p_thread, NULL); + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frames_recorded = 0; + for (frame_index = 0; frame_index < 3000; frame_index++) + { + frame(50); + if (profile_trace_recording()) + frames_recorded++; + } + profile_trace_request_stop(); + profile_trace_frame_boundary(); + __atomic_store_n(&p2p_running, 0, __ATOMIC_RELAXED); + pthread_join(thread, NULL); + finish(); + written.delay_milliseconds = 0; + check(written.records_in_span, "each record within its part while the writer is slow"); + check(written.counts[name_pass] == p2p_recorded, "a slow writer loses no p2p pass"); + check(written.parts >= 3, "parts while the writer is slow"); + check(written.writer_wait_ms > 0.0, "the wait for the writer is counted"); + check(written.counts[name_a] == frames_recorded * 50, "a slow writer loses nothing"); + check(written.counts[profile_trace_name("profile_wait")] >= 1, "the wait is a scope"); +} + +static int straddle_begun; +static int straddle_released; + +/* a p2p pass that lets go of its lock for slow work (p2p_resolve's DNS) */ +static void *straddling_pass(void *unused) +{ + (void)unused; + profile_trace_thread_register(_profile_track_p2p); + fake_lock(); + profile_trace_begin(name_pass); + fake_unlock(); + __atomic_store_n(&straddle_begun, 1, __ATOMIC_RELEASE); + while (!__atomic_load_n(&straddle_released, __ATOMIC_ACQUIRE)) + usleep(100); + fake_lock(); + profile_trace_end(name_pass); + fake_unlock(); + return NULL; +} + +static void straddle(int cut) +{ + pthread_t thread; + struct profile_trace_status status; + + forget_written(); + straddle_begun = straddle_released = 0; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frame(1); + pthread_create(&thread, NULL, straddling_pass, NULL); + while (!__atomic_load_n(&straddle_begun, __ATOMIC_ACQUIRE)) + usleep(100); + if (cut) + { + /* frames until a cut comes, while the pass is out of its lock */ + do + { + frame(50); + profile_trace_status(&status); + } + while (status.part < 2); + } + else + { + profile_trace_request_stop(); + profile_trace_frame_boundary(); + } + __atomic_store_n(&straddle_released, 1, __ATOMIC_RELEASE); + pthread_join(thread, NULL); + if (cut) + { + profile_trace_request_stop(); + profile_trace_frame_boundary(); + } + finish(); +} + +/* a pass begun in one recording and ended in the next (a stop, a re-arm and +a start between): its start is before the new origin, so it is dropped, and +counted in the new recording. concurrent: it ends while the start is made */ +static void straddle_restart(int concurrent) +{ + pthread_t thread; + + forget_written(); + straddle_begun = straddle_released = 0; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frame(1); + pthread_create(&thread, NULL, straddling_pass, NULL); + while (!__atomic_load_n(&straddle_begun, __ATOMIC_ACQUIRE)) + usleep(100); + profile_trace_request_stop(); + profile_trace_frame_boundary(); + finish(); + forget_written(); + advance(1000000); + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + if (concurrent) + { + __atomic_store_n(&straddle_released, 1, __ATOMIC_RELEASE); + frame(1); + } + else + { + frame(1); + __atomic_store_n(&straddle_released, 1, __ATOMIC_RELEASE); + } + pthread_join(thread, NULL); + frame(1); + profile_trace_request_stop(); + profile_trace_frame_boundary(); + finish(); +} + +static void straddle_checks(void) +{ + straddle(1); + check(written.counts[name_pass] == 1, "a pass across a cut is in the part it ended in, once"); + straddle(0); + check(written.counts[name_pass] == 0, "a pass that outlives its recording is not written"); + check(outstanding() == 0, "nothing left after a pass across a stop"); + straddle_restart(0); + check(written.counts[name_pass] == 0, "a pass across a restart is dropped, not given a wrapped start"); + check(written.dropped == 1, "and counted in the new recording"); + straddle_restart(1); + check(written.counts[name_pass] == 0, "a pass ending as the next recording starts is dropped"); + check(outstanding() == 0, "nothing left after a pass across a restart"); +} + +static void lifetime_checks(void) +{ + int cycle; + + /* many recordings, cut and not, stopped every way, with nothing left */ + for (cycle = 0; cycle < 40; cycle++) + { + int frames = cycle % 4 == 0 ? 2500 : 3; + int index; + + forget_written(); + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + for (index = 0; index < frames; index++) + frame(50); + if (cycle % 3 == 0) + { + profile_trace_map_loaded(); + profile_trace_frame_boundary(); + } + else if (cycle % 3 == 1) + { + profile_trace_request_stop(); + profile_trace_frame_boundary(); + } + else + { + profile_trace_shutdown(); + } + finish(); + if (outstanding() != 0) + { + check(0, "a recording leaves nothing allocated"); + break; + } + } + check(allocations_made > 80, "the cycles allocated"); + /* exit while armed, while writing, and twice */ + profile_trace_request_start(0.0, _profile_trace_when_game, 4); + fake_ready = 0; + profile_trace_shutdown(); + profile_trace_shutdown(); + check(outstanding() == 0, "shutdown while armed keeps nothing"); + fake_ready = 1; +} + +/* a real recording through the real writer, into the folder */ +static void file_checks(const char *folder) +{ + struct profile_trace_status status; + int frame_index; + int quoted; + + fake_folder = folder; + profile_trace_set_writer(NULL); + profile_trace_set_session_sampler(fake_session_sample); + quoted = profile_trace_name("quote\"back\\slash"); + fake_map = ""; + fake_map_name = ""; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + fake_role = "client"; + fake_players = 5; + fake_own_machine = 1; + fake_map = "levels\\a30\\a30"; + fake_map_name = "a30"; + for (frame_index = 0; frame_index < 2400; frame_index++) + { + if (frame_index == 2) + { + fake_map = "levels\\b30\\b30"; + fake_map_name = "b30"; + } + frame(40); + profile_trace_begin(name_texture); + profile_trace_begin(name_inner_aggregate); + advance(100); + profile_trace_end(name_inner_aggregate); + profile_trace_begin(name_aggregate_child); + advance(100); + profile_trace_end(name_aggregate_child); + profile_trace_end(name_texture); + profile_trace_begin(quoted); + advance(10); + profile_trace_end(quoted); + if (frame_index % 2 == 0) + { + profile_trace_begin(name_tick); + profile_trace_tick(); + advance(100); + profile_trace_end(name_tick); + } + advance(16000000); + } + profile_trace_shutdown(); + check(session_sample_calls > 0 && session_sample_calls < 2400, + "session sampling is periodic and not per frame"); + fake_role = "host"; + fake_players = 2; + fake_own_machine = -1; + fake_map = "levels\\a30\\a30"; + fake_map_name = "a30"; + check(outstanding() == 0, "the real writer frees both arenas"); + profile_trace_status(&status); + { + char name[64]; + char path[512]; + FILE *file; + + profile_json_choose_name(folder, "20261005-142233", "host", name, sizeof(name)); + check(strcmp(name, "profile_20261005-142233_host") == 0, "a free name is taken as it is"); + snprintf(path, sizeof(path), "%s/%s.part1.json", folder, name); + file = fopen(path, "wb"); + if (file) + fclose(file); + profile_json_choose_name(folder, "20261005-142233", "host", name, sizeof(name)); + check(strcmp(name, "profile_20261005-142233_host_2") == 0, "a name taken gets _2"); + remove(path); + } +} + +/* a folder that cannot be written: each part is logged and given up, its +.tmp gone, the arenas freed, and the recording still finishes */ +static void unwritable_checks(const char *folder) +{ + char missing[512]; + int frame_index; + + snprintf(missing, sizeof(missing), "%s/missing/deeper", folder); + fake_folder = missing; + last_log[0] = 0; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + for (frame_index = 0; frame_index < 2400; frame_index++) + frame(40); + profile_trace_request_stop(); + profile_trace_frame_boundary(); + finish(); + check(strstr(last_log, "cannot write") && strstr(last_log, "missing/deeper"), "a part that cannot be written is logged"); + check(outstanding() == 0, "a part that cannot be written frees its arena"); + fake_folder = folder; +} + +static int refusing_writer_start(void) +{ + return 0; +} + +/* a start that fails after it has allocated: nothing is kept, it says so, and +a recording of "game" mode is not armed again to fail at every game */ +static void release_path_checks(void) +{ + static const char *const what[] = { "the second arena refused", "the writer thread cannot start" }; + int fail, game; + + for (fail = 0; fail < 2; fail++) + { + for (game = 0; game < 2; game++) + { + struct profile_trace_status status; + char text[96]; + + snprintf(text, sizeof(text), "%s, %s mode", what[fail], game ? "game" : "now"); + forget_written(); + fake_ready = 1; + last_notice[0] = 0; + if (fail == 0) + allocations_allowed = 1; + else + profile_trace_set_writer(refusing_writer_start); + profile_trace_request_start(0.0, game ? _profile_trace_when_game : _profile_trace_when_now, 4); + frame(1); + allocations_allowed = -1; + profile_trace_set_writer(fake_writer_start); + profile_trace_status(&status); + check(outstanding() == 0, text); + check(status.state == _profile_trace_idle, text); + check(strstr(last_notice, fail == 0 ? "no memory for 4 MB" : "the writer thread cannot start") != NULL, text); + check(!profile_trace_recording(), text); + frame(1); + profile_trace_status(&status); + check(status.state == _profile_trace_idle && outstanding() == 0, text); + } + } +} + +/* a worst frame's ticks and longest scopes come from any depth of the frame: +game_tick sits under game_time_update, and the time a scope has of its own is +what ranks it (its parents would always come first otherwise) */ +static void worst_frame_checks(void) +{ + struct profile_trace_record game[16]; + struct profile_part *part = calloc(1, sizeof(*part)); + int frame_id = profile_trace_name("frame"); + int update = profile_trace_name("game_time_update"); + int tick = profile_trace_name("game_tick"); + int objects = profile_trace_name("game_tick.objects"); + int ai = profile_trace_name("game_tick.ai"); + int render = profile_trace_name("render"); + int bsp = profile_trace_name("render.bsp"); + int texture = profile_trace_name("texture"); + char text[65536]; + unsigned long count = 0, length; + FILE *file = tmpfile(); + const char *row; + + /* (milliseconds, as nanoseconds below) */ +#define WORST_RECORD(start_ms, duration_ms, id, level) \ + do { game[count].start = (start_ms) * 1000000ULL; game[count].duration = (duration_ms) * 1000000U; \ + game[count].name = (unsigned short)(id); game[count].depth = (level); game[count].track = 0; count++; } while (0) + WORST_RECORD(0, 100, frame_id, 0); + WORST_RECORD(0, 60, update, 1); + WORST_RECORD(0, 30, tick, 2); + WORST_RECORD(0, 20, objects, 3); + WORST_RECORD(30, 25, tick, 2); + WORST_RECORD(30, 22, ai, 3); + WORST_RECORD(60, 35, render, 1); + WORST_RECORD(60, 10, bsp, 2); + /* (an aggregate's time is a counter record, not a scope) */ + WORST_RECORD(5, 99, texture, PROFILE_TRACE_DEPTH_AGGREGATE_TIME); + WORST_RECORD(100, 5, frame_id, 0); +#undef WORST_RECORD + part->records[_profile_track_game] = game; + part->record_counts[_profile_track_game] = count; + part->name_count = profile_trace_name("worst_frame_last") + 1; + part->ticks = 2; + check(file != NULL, "a scratch file for the worst frames"); + if (!file) + { + free(part); + return; + } + check(profile_json_write(part, file), "a part with nested scopes is written"); + rewind(file); + length = fread(text, 1, sizeof(text) - 1, file); + text[length] = 0; + fclose(file); + row = strstr(text, "\"worst_frames\""); + check(row && strstr(row, "[0, 0.000, 100.000, 2, [[\"render\", 25.000], [\"game_tick.ai\", 22.000], " + "[\"game_tick.objects\", 20.000]]]"), + "the worst frame runs its two ticks under game_time_update and names the scopes with the most time of their own"); + check(row && strstr(row, "[1, 0.100, 5.000, 0, []]"), "a frame with no scopes in it has no ticks and no longest"); + free(part); +} + +/* the reset race: a p2p pass begun in one recording ends, from inside +the next recording's allocator seam, before that start resets the tracks' +counts. Only the track lock orders its bump before the reset, which +ThreadSanitizer checks (the reset moved out of the lock is a race) */ +static int race_armed; +static int race_ended; + +static void *race_pass(void *unused) +{ + (void)unused; + profile_trace_thread_register(_profile_track_p2p); + fake_lock(); + profile_trace_begin(name_pass); + fake_unlock(); + __atomic_store_n(&straddle_begun, 1, __ATOMIC_RELEASE); + /* (relaxed: no happens-before from the game thread's release) */ + while (!__atomic_load_n(&straddle_released, __ATOMIC_RELAXED)) + usleep(100); + fake_lock(); + profile_trace_end(name_pass); + fake_unlock(); + __atomic_store_n(&race_ended, 1, __ATOMIC_RELAXED); + return NULL; +} + +static void *race_allocate(unsigned long size) +{ + if (__atomic_load_n(&race_armed, __ATOMIC_RELAXED)) + { + __atomic_store_n(&race_armed, 0, __ATOMIC_RELAXED); + __atomic_store_n(&straddle_released, 1, __ATOMIC_RELAXED); + while (!__atomic_load_n(&race_ended, __ATOMIC_RELAXED)) + usleep(100); + } + return fake_allocate(size); +} + +static void reset_race_checks(void) +{ + pthread_t thread; + + profile_trace_set_allocator(race_allocate, fake_release); + forget_written(); + straddle_begun = straddle_released = 0; + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frame(1); + pthread_create(&thread, NULL, race_pass, NULL); + while (!__atomic_load_n(&straddle_begun, __ATOMIC_ACQUIRE)) + usleep(100); + profile_trace_request_stop(); + profile_trace_frame_boundary(); + finish(); + + forget_written(); + advance(1000000); + __atomic_store_n(&race_armed, 1, __ATOMIC_RELAXED); + profile_trace_request_start(0.0, _profile_trace_when_now, 4); + frame(1); + pthread_join(thread, NULL); + frame(1); + profile_trace_request_stop(); + profile_trace_frame_boundary(); + finish(); + check(written.counts[name_pass] == 0, "the pass of the last recording is not written"); + check(written.dropped == 0, "a pass ended before the start is not counted in the new recording"); + check(outstanding() == 0, "the race recordings leave nothing allocated"); + profile_trace_set_allocator(fake_allocate, fake_release); +} + +int main(int argc, char **argv) +{ + profile_trace_set_clock(fake_clock); + profile_trace_set_track_lock(fake_lock, fake_unlock); + profile_trace_set_allocator(fake_allocate, fake_release); + profile_trace_set_log(quiet_log); + profile_trace_set_notify(fake_notify); + profile_trace_set_writer(fake_writer_start); + profile_trace_set_ready(fake_ready_test); + profile_trace_set_session(fake_session); + profile_trace_set_session_sampler(fake_session_sample); + gametype_checks(); + profile_trace_thread_register(_profile_track_game); + name_frame = profile_trace_name("frame"); + name_tick = profile_trace_name("game_tick"); + name_a = profile_trace_name("game_tick.objects"); + name_b = profile_trace_name("objects_update"); + name_c = profile_trace_name("deep"); + name_pass = profile_trace_name("p2p.pass"); + name_aggregate_child = profile_trace_name("aggregate_child"); + profile_trace_name_aggregate("texture"); + profile_trace_name_aggregate("render_model"); + name_texture = profile_trace_name("texture"); + name_inner_aggregate = profile_trace_name("render_model"); + fake_ready = 1; + written.records_in_span = 1; + + scope_checks(); + state_checks(); + stop_answer_checks(); + part_checks(); + straddle_checks(); + lifetime_checks(); + worst_frame_checks(); + release_path_checks(); + reset_race_checks(); + if (argc > 1) + { + file_checks(argv[1]); + unwritable_checks(argv[1]); + } + printf("%s (%d failures)\n", failures ? "FAIL" : "PASS", failures); + return failures != 0; +} diff --git a/tools/profile_fixture.py b/tools/profile_fixture.py new file mode 100644 index 00000000..79ecc683 --- /dev/null +++ b/tools/profile_fixture.py @@ -0,0 +1,66 @@ +"""Hand-written CPU recording parts for the report tests.""" + +import json +from pathlib import Path + + +def part(number, intervals, last, frames_before, ticks_before): + frames = 60 * len(intervals) + ticks = 30 * len(intervals) + header = { + "format": 1, "build": "0 debug profile", "platform": "windows", "role": "host", "own_machine": -1, + "map": "levels\\a30\\a30", "map_name": "a30", "gametype": "campaign", + "players": 3 if number == 1 else 4, "players_most": 4, "start_utc": "2026-10-05 14:22:33", + "recording": "profile_20261005-142233_host", "part": number, "last_part": last, + "first_frame": frames_before, "frames": frames, + "first_tick": ticks_before, "ticks": ticks, "start_s": float(intervals[0]), "duration_s": float(len(intervals)), + "stop_reason": "command" if last else "", "clock_read_ns": 21.5, "memory_used": 1000, "memory_limit": 16777216, + "writer_wait_ms": 0.0, "foreign_scopes": 0, "deep_scopes": 0, "unbalanced_scopes": 0, "dropped_scopes": 0, + "dropped_scopes": 0, + } + halo = {"header": header} + cpu_rows = [ + ["frame", frames, 8.3 * frames, 8.3, 41.2, 1.0, None], + ["game_tick", ticks, 3.2 * ticks, 3.2, 6.012, 0.5, 3.2], + ["game_tick.objects", ticks, 1.4 * ticks, 1.4, 12.1, 0.5, 1.4], + ["network_distributed_tick", ticks, 0.6 * ticks, 0.6, 4.0, 0.5, 0.6], + ["render", frames, 4.0 * frames, 4.0, 9.8, 1.0, None], + ] + worst = [[frames_before + 12, frames_before / 60.0 + 0.2, 41.2 - number, 2, + [["game_tick.objects", 12.1], ["render", 9.8], ["network_distributed_tick", 4.0]]]] + cpu = {"frames": frames, "ticks": ticks, + "columns": ["name", "count", "total_ms", "mean_ms", "max_ms", "per_frame", "per_tick_ms"], + "rows": cpu_rows, "worst_frames": {"columns": ["frame", "at_s", "frame_ms", "ticks", "longest"], + "rows": worst}} + return halo, cpu + + +def write_part(path, halo, cpu): + """the writer's layout: one item per line, the events last""" + lines = ['{"halo": {', '"header": ' + json.dumps(halo["header"])] + for name, table in halo.items(): + if name == "header": + continue + lines[-1] += "," + lines.append(f'"{name}": {{"columns": {json.dumps(table["columns"])}, "rows": [') + lines.extend(json.dumps(row) + ("," if index < len(table["rows"]) - 1 else "") + for index, row in enumerate(table["rows"])) + lines.append("]}") + lines[-1] += "}," + lines.append('"cpu_summary": ' + json.dumps(cpu) + ",") + lines.append('"traceEvents": [') + lines.append('{"ph":"M","name":"process_name","pid":1,"args":{"name":"halo host windows"}}') + lines.append("],") + lines.append('"displayTimeUnit": "ms"}') + Path(path).write_text("\n".join(lines) + "\n", encoding="utf-8") + + +def write_recording(folder, name="profile_20261005-142233_host", split=True): + """three parts of two intervals each, or the same six in one part""" + folder = Path(folder) + folder.mkdir(parents=True, exist_ok=True) + spans = [[0, 1], [2, 3], [4, 5]] if split else [[0, 1, 2, 3, 4, 5]] + for index, intervals in enumerate(spans): + halo, cpu = part(index + 1, intervals, index == len(spans) - 1, intervals[0] * 60, intervals[0] * 30) + write_part(folder / f"{name}.part{index + 1}.json", halo, cpu) + return folder / name diff --git a/tools/profile_fixture.summary.txt b/tools/profile_fixture.summary.txt new file mode 100644 index 00000000..1ba3af2a --- /dev/null +++ b/tools/profile_fixture.summary.txt @@ -0,0 +1,35 @@ +# halo profile summary, format 1 +# recording: profile_20261005-142233_host, parts 1-3 (complete) +# build: 0 debug profile, platform: windows, role: host, own_machine: - +# map: levels\a30\a30, players: 3 at start, 4 most +# recorded: 2026-10-05 14:22:33 UTC, 6.0 s, 180 ticks, 360 frames, stopped: command +# problems: none +# units: ms = milliseconds + +## columns +scope CPU scope name (a profile section or frame timer); nested names use "." +count times the scope ran in the recording +total_ms summed inclusive time (children included), milliseconds +mean_ms total_ms / count +max_ms longest single run; aggregate sections: largest summed time in one frame +per_frame count / frames recorded +per_tick_ms total_ms / ticks recorded (game_tick.* and network_distributed_tick* only) +frame frame number in the recording +at_s seconds from the start of the recording to that frame +frame_ms that frame's duration +ticks game ticks that frame ran +longest scopes (ms) the frame's three scopes, at any depth, with the most time of their own (children not counted), name and that time + +## cpu scopes (top 40 by total_ms) +scope count total_ms mean_ms max_ms per_frame per_tick_ms +frame 360 2988.0 8.300 41.200 1.00 - +render 360 1440.0 4.000 9.800 1.00 - +game_tick 180 576.0 3.200 6.012 0.50 3.200 +game_tick.objects 180 252.0 1.400 12.100 0.50 1.400 +network_distributed_tick 180 108.0 0.600 4.000 0.50 0.600 + +## worst frames (10) +frame at_s frame_ms ticks longest scopes (ms) + 12 0.20 40.20 2 game_tick.objects 12.1, render 9.8, network_distributed_tick 4.0 + 132 2.20 39.20 2 game_tick.objects 12.1, render 9.8, network_distributed_tick 4.0 + 252 4.20 38.20 2 game_tick.objects 12.1, render 9.8, network_distributed_tick 4.0 diff --git a/tools/test_profile.py b/tools/test_profile.py new file mode 100644 index 00000000..d3533ecf --- /dev/null +++ b/tools/test_profile.py @@ -0,0 +1,569 @@ +"""Profiling build, CPU recorder, written parts and CPU report tests. +For local WSL runs in a Windows worktree, set HALO_GIT=git.exe. +""" + +import io +import json +import os +import re +import shlex +import shutil +import subprocess +import tarfile +from pathlib import Path +from types import SimpleNamespace + +import pytest + +from tools import linux_build, net_report, ninja_syntax, profile_fixture + +ROOT = Path(__file__).resolve().parent.parent +GIT = os.environ.get("HALO_GIT", "git") + + +# ---------- the build switch + + +def test_configuration_defines(): + assert linux_build.configuration_defines(SimpleNamespace()) == [] + assert linux_build.configuration_defines(SimpleNamespace(port_release=True)) == ["-DHALO_RELEASE"] + assert linux_build.configuration_defines(SimpleNamespace(port_release=True, port_profile=True)) == [ + "-DHALO_RELEASE", "-DHALO_PROFILE"] + + +def test_every_native_build_takes_the_configuration_defines(): + # (the guest, the game and the platform layer of all three: one place + # decides what --release and --profile define) + for name in ("linux_build.py", "windows_build.py", "android_build.py"): + text = (ROOT / "tools" / name).read_text(encoding="utf-8") + assert "configuration_defines(sln)" in text, name + assert '["-DHALO_RELEASE"] if' not in text, name + + +def test_profile_refuses_pgo_training(): + with pytest.raises(ValueError, match="--pgo=train"): + linux_build.check_profile_options(True, "train") + linux_build.check_profile_options(True, "use") + linux_build.check_profile_options(True, "off") + linux_build.check_profile_options(False, "train") + + +def test_linux_build_compiles_with_the_profile_define(monkeypatch): + monkeypatch.chdir(ROOT) + out = io.StringIO() + linux_build.generate_linux_build(ninja_syntax.Writer(out), SimpleNamespace( + build_dir=Path("build"), linux_cc="clang", compiler_launcher=None, port_release=False, port_lto="off", + port_portable=True, port_pgo="off", port_pgo_profile=None, port_profile=True)) + # (ninja_syntax wraps long lines with " $"; Windows paths have backslashes) + text = re.sub(r" \$\n *", " ", out.getvalue()).replace("\\", "/") + for obj in ("build/linux/obj/source/game/game.o", "build/linux/obj/port/linux/src/p2p.o"): + block = text[text.index(f"build {obj}:"):] + cflags = next(line for line in block.splitlines() if line.strip().startswith("cflags = ")) + assert "-DHALO_PROFILE" in cflags, obj + + +# ---------- the recording's C units (tools/profile_check.c) + +PROFILE_SOURCES = ["port/linux/src/profile_trace.c", "port/linux/src/profile_json.c"] + + +def check_compiler(): + """a C compiler of this machine with POSIX threads, or None (Windows has + them only through the port's own layer, so the check runs on Linux and + in WSL)""" + if os.name == "nt": + return None + for name in ("clang", "cc", "gcc"): + if shutil.which(name): + return name + return None + + +def build_check(tmp_path, sanitizers): + compiler = check_compiler() + if not compiler: + pytest.skip("needs a C compiler with POSIX threads (Linux, WSL)") + program = tmp_path / ("profile_check" + "".join(f"_{name}" for name in sanitizers)) + flags = [f"-fsanitize={','.join(sanitizers)}", "-fno-omit-frame-pointer"] if sanitizers else [] + built = subprocess.run([compiler, "-std=gnu11", "-Wall", "-Werror", "-DHALO_PROFILE", "-pthread", "-g", "-O1", + *flags, "-idirafter", "port/linux/include", "-Iport/linux/src", + "-o", str(program), + "tools/profile_check.c", *PROFILE_SOURCES], + cwd=ROOT, capture_output=True, text=True) + if built.returncode != 0 and sanitizers and "sanitize" in built.stderr: + pytest.skip(f"{compiler} cannot build with {sanitizers}") + assert built.returncode == 0, built.stderr[-4000:] + return program + + +def run_check(program, folder): + folder.mkdir(exist_ok=True) + result = subprocess.run([str(program), str(folder)], capture_output=True, text=True, timeout=300, + env={**os.environ, "ASAN_OPTIONS": "detect_leaks=1", "TSAN_OPTIONS": "halt_on_error=1"}) + assert result.returncode == 0, result.stdout + result.stderr[-4000:] + assert "PASS" in result.stdout + + +def test_check_program_passes(tmp_path): + run_check(build_check(tmp_path, []), tmp_path / "out") + + +def test_check_program_has_no_leaks_or_memory_errors(tmp_path): + """AddressSanitizer and LeakSanitizer over every recording the check + makes: arenas, the writer's files, the parts""" + run_check(build_check(tmp_path, ["address", "undefined"]), tmp_path / "out") + + +def test_check_program_has_no_data_races(tmp_path): + """ThreadSanitizer: the p2p track, the writer hand-off, the recording + flag""" + run_check(build_check(tmp_path, ["thread"]), tmp_path / "out") + + +@pytest.fixture(scope="module") +def written_parts(tmp_path_factory): + folder = tmp_path_factory.mktemp("written") + run_check(build_check(tmp_path_factory.mktemp("build"), []), folder) + recordings = {} + for path in folder.glob("*.part*.json"): + try: + header = json.loads(path.read_text(encoding="utf-8"))["halo"]["header"] + except (OSError, json.JSONDecodeError, KeyError): + continue + recordings.setdefault(header["recording"], []).append((header["part"], path)) + parts = max(recordings.values(), key=len) + assert len(parts) >= 2, "the real C recording is split into parts" + return [path for number, path in sorted(parts)] + + +def test_written_parts_are_traces(written_parts): + for path in written_parts: + text = path.read_text(encoding="utf-8") + trace = json.loads(text) + assert list(trace) == ["halo", "cpu_summary", "traceEvents", "displayTimeUnit"] + assert text.startswith('{"halo": {\n"header": {') + assert trace["halo"]["header"]["last_part"] == (path == written_parts[-1]) + header = trace["halo"]["header"] + assert (header["role"], header["own_machine"], header["players"], header["players_most"]) == ( + "host", -1, 2, 5) + assert (header["map_name"], header["gametype"]) == ("b30", "campaign") + lines = text.splitlines() + events = lines.index('"traceEvents": [') + # one event a line, the scopes in order of their start + starts = [json.loads(line.rstrip(","))["ts"] for line in lines[events + 1:-2] if '"ph":"X"' in line] + assert starts == sorted(starts) + assert '"quote\\"back\\\\slash"' in text or path != written_parts[0] + + +def test_written_parts_nest_on_tracks(written_parts): + trace = json.loads(written_parts[0].read_text(encoding="utf-8")) + names = {event["args"]["name"] for event in trace["traceEvents"] if event["ph"] == "M"} + assert {"game", "p2p"} <= names + scopes = [event for event in trace["traceEvents"] if event["ph"] == "X" and event["tid"] == 1] + frame = next(event for event in scopes if event["name"] == "frame") + inside = [event for event in scopes if frame["ts"] <= event["ts"] < frame["ts"] + frame["dur"] and event is not frame] + assert inside and all(event["ts"] + event["dur"] <= frame["ts"] + frame["dur"] + 0.001 for event in inside) + + +def test_written_parts_import_in_perfetto(written_parts): + """trace_processor's import, when the perfetto package is installed (run + by hand on a real recording otherwise)""" + trace_processor = pytest.importorskip("perfetto.trace_processor") + with trace_processor.TraceProcessor(trace=str(written_parts[0])) as processor: + errors = processor.query("select name, value from stats where severity = 'error' and value > 0") + rows = list(errors) + assert not rows, [(row.name, row.value) for row in rows] + + +def test_written_parts_read_by_the_report(written_parts): + recording = net_report.Recording(written_parts[0]) + assert recording.complete and not recording.warnings + cpu_rows = [dict(zip(summary["columns"], row)) for summary in + [json.loads(path.read_text(encoding="utf-8"))["cpu_summary"] for path in written_parts] + for row in summary["rows"]] + totals = {} + for row in cpu_rows: + totals[row["name"]] = totals.get(row["name"], 0) + row["count"] + assert totals["texture"] == 2400 + assert totals["render_model"] == 2400 + assert totals["aggregate_child"] == 2400 + frames = sum(1 for path in written_parts for event in json.loads(path.read_text(encoding="utf-8"))["traceEvents"] + if event["ph"] == "X" and event["name"] == "frame") + assert recording.cpu["frames"] == frames + + +# ---------- tools/net_report.py + +EXPECTED_SUMMARY = ROOT / "tools" / "profile_fixture.summary.txt" + + +def cpu_recording(tmp_path, role="host"): + base = tmp_path / f"compat_{role}" + for number, start, duration in ((1, 0.0, 1.25), (2, 1.25, 2.75)): + halo, cpu = profile_fixture.part(number, [number - 1], number == 2, 0, 0) + halo["header"].update(role=role, start_s=start, duration_s=duration) + profile_fixture.write_part(Path(f"{base}.part{number}.json"), {"header": halo["header"]}, cpu) + return net_report.Recording(base) + + +def test_cpu_only_duration_comes_from_each_part_header(tmp_path): + recording = cpu_recording(tmp_path) + assert recording.select() == 4.0 + assert recording.select(0.5, 3.0) == 2.5 + assert recording.select(5.0, 6.0) == 0.0 + + + +def test_cpu_report_prints_and_exports_only_cpu_measurements(tmp_path, capsys): + base = profile_fixture.write_recording(tmp_path) + directory = tmp_path / "csv" + assert net_report.main([str(base), "--no-summary", "--csv", str(directory)]) == 0 + output = capsys.readouterr().out + assert "## cpu scopes" in output and "## worst frames" in output + assert "## traffic" not in output and "## message types" not in output + assert "wire_rtt_ms" not in output and "msgs/s" not in output + assert {path.name.rsplit(".", 2)[1] for path in directory.glob("*.csv")} == {"cpu", "worst_frames"} + + +@pytest.fixture +def host(tmp_path): + return profile_fixture.write_recording(tmp_path) + + +def test_report_summary_is_the_expected_one(host): + assert net_report.main([str(host) + ".part2.json"]) == 0 + written = Path(str(host) + ".summary.txt").read_text(encoding="ascii") + assert written == EXPECTED_SUMMARY.read_text(encoding="ascii") + assert len(written.splitlines()) <= net_report.SUMMARY_LINE_LIMIT + + +def test_report_uses_players_most_and_accepts_old_headers(tmp_path): + base = profile_fixture.write_recording(tmp_path / "legacy") + paths = [Path(f"{base}.part{number}.json") for number in (1, 2, 3)] + for index, path in enumerate(paths): + data = json.loads(path.read_text(encoding="utf-8")) + header = data["halo"]["header"] + for key in ("map_name", "gametype", "players_most"): + header.pop(key, None) + header["players"] = 1 + index + profile_fixture.write_part(path, data["halo"], data["cpu_summary"]) + old_parts_report = net_report.Recording(paths[0]) + old_summary = net_report.summary_lines(old_parts_report, None, None, 40) + assert any("players: 1 at start, 3 most" in line for line in old_summary) + assert net_report.main([str(paths[0]), "--no-summary"]) == 0 + + +def test_report_summary_uses_current_players_most(tmp_path): + base = profile_fixture.write_recording(tmp_path / "current") + last = Path(f"{base}.part3.json") + data = json.loads(last.read_text(encoding="utf-8")) + data["halo"]["header"]["players_most"] = 9 + profile_fixture.write_part(last, data["halo"], data["cpu_summary"]) + recording = net_report.Recording(Path(f"{base}.part1.json")) + summary = net_report.summary_lines(recording, None, None, 40) + assert any("players: 3 at start, 9 most" in line for line in summary) + + +def test_report_merges_parts_as_one(tmp_path): + split = profile_fixture.write_recording(tmp_path / "split") + whole = profile_fixture.write_recording(tmp_path / "whole", split=False) + assert net_report.main([str(split), "--no-summary", "--csv", str(tmp_path / "split_csv")]) == 0 + assert net_report.main([str(whole), "--no-summary", "--csv", str(tmp_path / "whole_csv")]) == 0 + for table in sorted((tmp_path / "split_csv").glob("*.csv")): + if table.name.endswith(".worst_frames.csv"): + continue + assert table.read_text() == (tmp_path / "whole_csv" / table.name).read_text(), table.name + + +def test_report_warns_about_a_missing_part(host, capsys): + Path(str(host) + ".part2.json").unlink() + net_report.main([str(host), "--no-summary"]) + captured = capsys.readouterr() + assert "part 2 of profile_20261005-142233_host is missing" in captured.err + assert "(incomplete)" in captured.out + + +def test_report_warns_about_no_last_part(host, capsys): + Path(str(host) + ".part3.json").unlink() + net_report.main([str(host), "--no-summary"]) + assert "has no last part: the recording is incomplete" in capsys.readouterr().err + + +def test_summary_glossary_has_one_line_per_printed_column(host): + net_report.main([str(host)]) + lines = Path(str(host) + ".summary.txt").read_text(encoding="ascii").splitlines() + start = lines.index("## columns") + 1 + end = lines.index("", start) + glossary = [re.split(r"\s{2,}", line, maxsplit=1)[0] for line in lines[start:end]] + printed = set() + for index, line in enumerate(lines[end:], end): + if line.startswith("## ") and index + 1 < len(lines) and lines[index + 1] not in ("", "(none)"): + printed.update(re.split(r"\s{2,}", lines[index + 1].strip())) + assert printed and len(glossary) == len(set(glossary)) + assert set(glossary) == printed + + +def test_summary_file_ignores_top(host): + assert net_report.main([str(host), "--top", "1"]) == 0 + written = Path(str(host) + ".summary.txt").read_text(encoding="ascii") + assert written == EXPECTED_SUMMARY.read_text(encoding="ascii") + assert len(written.splitlines()) <= net_report.SUMMARY_LINE_LIMIT + + +def test_report_top_limits_the_printed_tables(host, capsys): + net_report.main([str(host), "--no-summary", "--top", "1"]) + assert "... 4 more rows (net_report.py --top N)" in capsys.readouterr().out + + +def test_report_says_cpu_tables_cover_the_whole_recording(host, capsys): + net_report.main([str(host), "--no-summary", "--from", "2", "--to", "4"]) + out = capsys.readouterr().out + assert "# window: 2.0 s selected (seconds 2 to 4)" in out + assert "cpu tables, ticks and frames cover the whole recording" in out + assert "## cpu scopes (top 40 by total_ms, whole recording)" in out + assert "## worst frames (10, whole recording)" in out + + +def test_report_names_the_broken_part(host, capsys): + path = Path(str(host) + ".part2.json") + path.write_text(path.read_text().replace('"cpu_summary"', '"cpu_summery"'), encoding="utf-8") + assert net_report.main([str(host), "--no-summary"]) == 1 + err = capsys.readouterr().err + assert err.startswith("net_report: ") and "part2" in err and "cpu_summary" in err + path.write_text(Path(str(host) + ".part1.json").read_text().replace('"last_part"', '"last_prt"'), encoding="utf-8") + assert net_report.main([str(host), "--no-summary"]) == 1 + assert "last_part" in capsys.readouterr().err + + +def test_windows_compile_command_parser_preserves_quoted_define_and_paths(): + command = ('clang -I"source/saved films" -include port\\windows\\include\\prefix.h ' + '-I"C:\\Program Files\\LLVM\\include" ' + '-DHALO_BUILD_FLAVOR=\\"release\\" source\\game.c -o build\\game.o') + assert parse_compile_command(command, windows=True) == [ + "clang", "-Isource/saved films", "-include", "port/windows/include/prefix.h", + "-IC:/Program Files/LLVM/include", '-DHALO_BUILD_FLAVOR="release"', + "source/game.c", "-o", "build/game.o"] + + +def test_console_words_and_record_seconds_use_the_real_parser(tmp_path): + compiler = check_compiler() + if not compiler: + pytest.skip("needs a C compiler (Linux, WSL)") + text = (ROOT / "port/linux/game/profile_console.c").read_text() + word = text[text.index("static char const *profile_console_word("):text.index("/* ---------- public code */")] + command = text[text.index("boolean profile_console_command("):text.rindex("\n#endif")] + program = tmp_path / "console_check" + code = tmp_path / "console_check.c" + # Compile the game's actual parsing functions; only their external game effects are stubbed. + code.write_text(r''' +#include +#include +#include +#include "profile_trace.h" +typedef int boolean; +#define TRUE 1 +#define FALSE 0 +static int requests; +static double accepted_seconds; +static void profile_console_install(void) {} +static long config_integer(const char *name) { (void)name; return 32; } +static void console_printf(boolean flag, const char *format, ...) { (void)flag; (void)format; } +int profile_trace_request_start(double seconds, int when, long memory) { + assert(when == _profile_trace_when_now && memory == 32); + requests++; accepted_seconds = seconds; return _profile_trace_answer_armed; +} +int profile_trace_request_stop(void) { return _profile_trace_answer_not_recording; } +void profile_trace_status(struct profile_trace_status *status) { memset(status, 0, sizeof(*status)); } +''' + word + command + r''' +int main(void) { + assert(strcmp(profile_console_word(" (PROFILE_RECORD 1.5)", "profile_record"), "1.5)") == 0); + assert(profile_console_word("profile_record_extra", "profile_record") == NULL); + assert(profile_console_command("PROFILE_RECORD 1.5")); + assert(requests == 1 && accepted_seconds == 1.5); + assert(profile_console_command("profile_record x")); + assert(requests == 1); + assert(profile_console_command("profile_record -1")); + assert(requests == 1); + assert(profile_console_command("profile_record")); + assert(requests == 2 && accepted_seconds == 0.0); + assert(!profile_console_command("profile_record_extra 1")); + return 0; +} +''') + subprocess.run([compiler, "-std=gnu11", "-Wall", "-Werror", "-DHALO_PROFILE", + "-I", str(ROOT / "port/linux/include"), str(code), "-o", str(program)], check=True) + subprocess.run([str(program)], check=True) + + +# ---------- a normal build is unchanged + +PROFILE_PREFIXES = ("profile_trace_", "profile_net_", "profile_json_", "profile_overlay_") + + +def parse_compile_command(command, windows=False): + """Split a Ninja C command, normalizing Windows path separators without changing escaped quotes.""" + if windows: + command = re.sub(r'\\(?!")', "/", command) + return shlex.split(command, posix=True) + + +def unavailable(reason): + """a run that asks for the check (HALO_PROFILE_BASE or HALO_PROFILE_OBJECTS) must not skip it silently""" + if os.environ.get("HALO_PROFILE_BASE") or os.environ.get("HALO_PROFILE_OBJECTS"): + pytest.fail(reason) + pytest.skip(reason) + + +def preprocess_flags(): + """the game's or the platform layer's compile flags for this computer's + build, as ninja has them, without HALO_PROFILE and without what makes + an object; absolute where they name a generated file""" + missing = [name for name in ("clang", "ninja") if not shutil.which(name)] + if not (ROOT / "build.ninja").is_file(): + missing.append("a configured build (build.ninja)") + if missing: + unavailable("needs " + ", ".join(missing)) + # (HALO_PROFILE_OBJECTS names another configured flavour's object folder, such as build/android/guest/obj, + # where this computer has no build of its own) + objects = os.environ.get("HALO_PROFILE_OBJECTS") or f"build/{'windows' if os.name == 'nt' else 'linux'}/obj" + + def flags(object_path): + listing = subprocess.run(["ninja", "-t", "commands", object_path], cwd=ROOT, capture_output=True, text=True) + if listing.returncode != 0: + unavailable(f"needs a build.ninja that has {object_path}") + command = listing.stdout.strip().splitlines()[-1] + words = parse_compile_command(command, windows=os.name == "nt") + while words and not words[0].startswith("-"): + words = words[1:] + # (the Android guest's command is a pipeline whose first compile makes assembly) + words = words[:words.index("&&")] if "&&" in words else words + kept, skip = [], False + for word in words: + if skip: + skip = False + elif word in ("-MF", "-o", "-c"): + skip = True + elif word in ("-MMD", "-S") or word == "-DHALO_PROFILE" or word.startswith(("-flto", "-fprofile-use")): + continue + elif word.endswith(".c") and not word.startswith("-"): + continue + elif word.startswith(("build/", "build\\")): + kept.append(str(ROOT / word)) + elif word.startswith(("-Ibuild/", "-Ibuild\\")): + kept.append("-I" + str(ROOT / word[2:])) + else: + kept.append(word) + return kept + + flag_sets = { + "game": flags(f"{objects}/source/game/game.o"), + "platform": flags(f"{objects}/port/linux/src/p2p.o"), + "port_game": flags(f"{objects}/port/linux/game/network_coop.o"), + } + # (only a missing 32-bit C library is "no build here"; any other error is a wrong command, which must not hide) + probe = subprocess.run(["clang", *flag_sets["game"], "-E", "-P", "-x", "c", "-"], cwd=ROOT, + input="#include \n#include \n", + capture_output=True, text=True) + if probe.returncode != 0: + reason = "the game's flags do not preprocess: " + next((line for line in probe.stderr.splitlines() if "error" in line), "")[:200] + if "bits/libc-header-start.h" in probe.stderr: + pytest.skip("needs a 32-bit C library (gcc-multilib); " + reason) + pytest.fail(reason) + return flag_sets + + +def flags_for(path, flag_sets): + if path.startswith("port/linux/src/"): + return flag_sets["platform"] + if path.startswith("port/linux/game/"): + return flag_sets["port_game"] + return flag_sets["game"] + + +def preprocessed(tree, path, flags): + # (path None: an empty file, which is all that the forced includes leave of a file that is empty) + arguments = ["-x", "c", "-"] if path is None else [path] + # (__DATE__ and __TIME__ pinned: main.c prints them, and the two trees can be preprocessed a second apart) + pinned = ["-Wno-builtin-macro-redefined", '-D__DATE__="Jan 1 2000"', '-D__TIME__="00:00:00"'] + result = subprocess.run(["clang", *flags, *pinned, "-E", "-P", *arguments], cwd=tree, + input="" if path is None else None, + capture_output=True, text=True) + assert result.returncode == 0, f"{path}: {result.stderr[-2000:]}" + # (only the tokens: blank lines and layout differ where #ifdef blocks were) + return " ".join(result.stdout.split()) + + +def includers_of_changed_headers(base, already): + """the C files that include a header that changed since the base: a header's #ifdef can change them too""" + def names(*arguments): + return subprocess.run([GIT, *arguments], cwd=ROOT, capture_output=True, text=True, check=True).stdout.split() + + added = set(names("diff", "--name-only", "--diff-filter=A", base, "HEAD", "--", "*.c")) + found = set() + for header in names("diff", "--name-only", "--diff-filter=M", base, "HEAD", "--", "*.h"): + pattern = r'#[ ]*include[ ]*[<"]([^">]*/)?' + re.escape(header.rsplit("/", 1)[-1]) + '[">]' + for path in names("grep", "-l", "-E", pattern, "HEAD", "--", "*.c"): + path = path.split(":", 1)[1] + if path.startswith(("source/", "port/linux/src/", "port/linux/game/")) and path not in added: + found.add(path) + return sorted(found - set(already)) + + +@pytest.mark.skipif(not os.environ.get("HALO_PROFILE_BASE"), reason="HALO_PROFILE_BASE names the base commit") +def test_normal_build_preprocesses_as_before(tmp_path): + base = os.environ["HALO_PROFILE_BASE"] + flag_sets = preprocess_flags() + changed = subprocess.run([GIT, "diff", "--name-only", "--diff-filter=M", base, "HEAD", "--", "*.c"], cwd=ROOT, + capture_output=True, text=True, check=True).stdout.split() + assert changed, "no C file changed since the base" + changed += includers_of_changed_headers(base, changed) + tree = tmp_path / "base" + tree.mkdir() + archive = subprocess.run([GIT, "archive", "--format=tar", base], cwd=ROOT, check=True, capture_output=True).stdout + with tarfile.open(fileobj=io.BytesIO(archive)) as reference: + reference.extractall(tree) + for path in changed: + flags = flags_for(path, flag_sets) + assert preprocessed(tree, path, flags) == preprocessed(ROOT, path, flags), path + + +def test_new_files_are_empty_in_a_normal_build(): + flag_sets = preprocess_flags() + # (found, not listed: a new profile_*.c that forgets its #ifdef shows up here) + paths = sorted(str(path.relative_to(ROOT)).replace("\\", "/") + for directory in ("port/linux/src", "port/linux/game") + for path in (ROOT / directory).glob("profile_*.c")) + assert set(paths) == {*PROFILE_SOURCES, "port/linux/game/profile_console.c"}, paths + for path in paths: + flags = flags_for(path, flag_sets) + assert preprocessed(ROOT, path, flags) == preprocessed(ROOT, None, flags), path + + +def test_normal_build_has_no_profiling_symbols(): + ninja_file = ROOT / "build.ninja" + if not ninja_file.is_file(): + pytest.skip("needs a configured build (build.ninja)") + if "-DHALO_PROFILE" in ninja_file.read_text(encoding="utf-8"): + pytest.skip("a profiling build is configured") + nm = shutil.which("llvm-nm") or shutil.which("nm") + if os.name == "nt" or os.environ.get("HALO_PROFILE_OBJECTS"): + folder = ROOT / (os.environ.get("HALO_PROFILE_OBJECTS") or "build/windows/obj") + objects = sorted(str(path) for path in folder.rglob("*.o")) + else: + objects = [str(ROOT / "build/linux/halo")] if (ROOT / "build/linux/halo").is_file() else [] + if not nm: + unavailable("needs nm") + if not objects: + unavailable("needs a built normal build (build/windows/obj/**/*.o, build/linux/halo, or the objects in HALO_PROFILE_OBJECTS)") + found, words, defined = set(), set(), 0 + for start in range(0, len(objects), 200): + listing = subprocess.run([nm, "--defined-only", *objects[start:start + 200]], capture_output=True, text=True) + # (an nm that cannot read the objects, such as bitcode from --lto, lists nothing and would pass) + assert listing.returncode == 0, listing.stderr[-1000:] + words |= {word.lstrip("_") for word in listing.stdout.split()} + defined += sum(len(line.split()) == 3 for line in listing.stdout.splitlines()) + found = {word for word in words if word.startswith(PROFILE_PREFIXES)} + # (a count, not a named symbol: link-time optimization inlines the functions that have one caller. The game's + # objects list thousands; an unreadable or a near-empty set lists none) + assert defined >= 300, f"nm lists {defined} defined symbols: it cannot read these objects" + assert not found, sorted(found)[:20] diff --git a/tools/windows_build.py b/tools/windows_build.py index f410e935..55489cb1 100644 --- a/tools/windows_build.py +++ b/tools/windows_build.py @@ -19,7 +19,7 @@ from pathlib import Path from typing import Any, Dict, List, Optional from .linux_build import (LINUX_PROFILE, MINIUPNPC_DIR, OPTIMISATION, WINDOWS_PROFILE, XDK_INCLUDE, lto_mode, - march_flag, miniupnpc_sources, pgo_mode, compile_launcher, game_defines_and_includes, + march_flag, miniupnpc_sources, pgo_mode, compile_launcher, configuration_defines, game_defines_and_includes, game_sources, musl_math_cflags, musl_math_sources, pgo_profile, profile_use_flags, xdk_headers) from .embed_assets import hud_assets_build, hud_configure_inputs @@ -304,8 +304,8 @@ def generate_windows_build(n: Writer, sln: Any) -> None: # (a debug build checks its stack frames (/GS), and stops at the first # one overrun, as at the first failed assertion; a release build does # not, so that an overrun nobody has met cannot end a game) - abi = " ".join(WINDOWS_ABI_FLAGS + [march_flag(sln)] + (["-DHALO_RELEASE"] if getattr(sln, "port_release", False) - else ["-fstack-protector-strong"])) + abi = " ".join(WINDOWS_ABI_FLAGS + [march_flag(sln)] + configuration_defines(sln) + + ([] if getattr(sln, "port_release", False) else ["-fstack-protector-strong"])) sdl_include = SDL_DIR / "include" libs = " ".join( [_quote(SDL_DIR / "lib" / "x86" / "SDL3.lib")]