Profiling, but also SLOWS DOWN Game???

main
Cameron Murphy Reikes 2 years ago
parent 9259536370
commit a8157f076b

2
.gitignore vendored

@ -1,3 +1,5 @@
# profiling results
*.spall
compile_commands.json
.cache/
enc_temp_folder/

@ -58,6 +58,7 @@
<UseDebugLibraries>true</UseDebugLibraries>
<PlatformToolset>v143</PlatformToolset>
<CharacterSet>Unicode</CharacterSet>
<EnableASAN>false</EnableASAN>
</PropertyGroup>
<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug No Host|x64'" Label="Configuration">
<ConfigurationType>Application</ConfigurationType>
@ -140,7 +141,7 @@
<ClCompile>
<WarningLevel>Level3</WarningLevel>
<SDLCheck>true</SDLCheck>
<PreprocessorDefinitions>_DEBUG;_CONSOLE;%(PreprocessorDefinitions);DEBUG_RENDERING</PreprocessorDefinitions>
<PreprocessorDefinitions>_DEBUG;_CONSOLE;%(PreprocessorDefinitions);DEBUG_RENDERING;SERVER_ADDRESS="127.0.0.1"</PreprocessorDefinitions>
<ConformanceMode>true</ConformanceMode>
<AdditionalIncludeDirectories>$(ProjectDir)\thirdparty\enet\include;$(ProjectDir)\thirdparty\Chipmunk2D\include\chipmunk;$(ProjectDir)\thirdparty;$(ProjectDir)\thirdparty\Chipmunk2D\include;$(ProjectDir)\thirdparty\minilzo;$(ProjectDir)\thirdparty\opus\include</AdditionalIncludeDirectories>
<TreatWarningAsError>true</TreatWarningAsError>

@ -3,6 +3,8 @@
#include "queue.h"
#include "stdbool.h"
#include "types.h"
#define PROFILING_IMPL
#include "profiling.h"
#include "ipsettings.h" // debug/developer settings
@ -73,7 +75,7 @@ bool cloaking_active(GameState *gs, Entity *e)
{
// cloaking doesn't work for first 1/2 second of game because when initializing
// everything needs to be uncloaked
return gs->time >= 0.5 && (gs->time - e->time_was_last_cloaked) <= TIMESTEP * 2.0;
return time(gs) >= 0.5 && (time(gs) - e->time_was_last_cloaked) <= TIMESTEP * 2.0;
}
bool is_cloaked(GameState *gs, Entity *e, Entity *this_players_perspective)
@ -391,7 +393,6 @@ void grid_create(GameState *gs, Entity *e)
create_body(gs, e);
}
void entity_set_rotation(Entity *e, double rot)
{
assert(e->body != NULL);
@ -1339,7 +1340,9 @@ SerMaybeFailure ser_server_to_client(SerState *ser, ServerToClient *s)
SER_ASSERT(cur_next_entity <= ser->max_entity_index);
SER_VAR(&s->your_player);
SER_VAR(&gs->time);
SER_VAR(&gs->tick);
SER_VAR(&gs->subframe_time);
SER_MAYBE_RETURN(ser_V2(ser, &gs->goldpos));
@ -1661,7 +1664,7 @@ static void cloaking_shield_callback_func(cpShape *shape, cpContactPointSet *poi
GameState *gs = entitys_gamestate(from_cloaking_box);
Entity *to_cloak = cp_shape_entity(shape);
to_cloak->time_was_last_cloaked = gs->time;
to_cloak->time_was_last_cloaked = time(gs);
to_cloak->last_cloaked_by_squad = from_cloaking_box->owning_squad;
}
@ -1801,7 +1804,13 @@ cpVect thruster_force(Entity *box)
uint64_t tick(GameState *gs)
{
return (uint64_t)floor(gs->time / ((double)TIMESTEP));
// return (uint64_t)floor(gs->time / ((double)TIMESTEP));
return gs->tick;
}
double time(GameState *gs)
{
return ((double)gs->tick * TIMESTEP) + gs->subframe_time;
}
Entity *grid_to_build_on(GameState *gs, cpVect world_hand_pos)
@ -2110,18 +2119,33 @@ void exit_seat(GameState *gs, Entity *seat_in, Entity *p)
cpBodySetVelocity(p->body, cpBodyGetVelocity(box_grid(seat_in)->body));
}
void process_fixed_timestep(GameState *gs)
void process(struct GameState *gs, double dt, bool is_subframe)
{
process(gs, TIMESTEP);
}
void process(GameState *gs, double dt)
PROFILE_SCOPE("Gameplay processing")
{
assert(gs->space != NULL);
gs->time += dt;
PROFILE_SCOPE("subframe stuff")
{
if (is_subframe)
{
gs->subframe_time += dt;
while (gs->subframe_time > TIMESTEP)
{
gs->subframe_time -= TIMESTEP;
gs->tick++;
}
}
else
{
assert(gs->subframe_time == 0.0);
gs->tick++;
}
}
// process sun gravity
PROFILE_SCOPE("sun gravity")
{
SUNS_ITER(gs)
{
Entity *from_sun = i.sun;
@ -2145,8 +2169,11 @@ void process(GameState *gs, double dt)
}
#endif
}
}
PROFILE_SCOPE("input processing")
{
// process input
PLAYERS_ITER(gs->players, player)
{
if (player->input.take_over_squad >= 0)
@ -2221,7 +2248,7 @@ void process(GameState *gs, double dt)
{
p->goldness += 0.1;
p->damage = 0.0;
gs->goldpos = (cpVect){.x = hash11((float)gs->time) * 20.0, .y = hash11((float)gs->time - 13.6) * 20.0};
gs->goldpos = (cpVect){.x = hash11((float)time(gs)) * 20.0, .y = hash11((float)time(gs) - 13.6) * 20.0};
}
#if 1
cpVect world_hand_pos = get_world_hand_pos(gs, &player->input, p);
@ -2416,15 +2443,17 @@ void process(GameState *gs, double dt)
p->damage = clamp01(p->damage);
}
}
// process entities
PROFILE_SCOPE("process entities")
{
for (size_t i = 0; i < gs->cur_next_entity; i++)
{
Entity *e = &gs->entities[i];
if (!e->exists)
continue;
// instant death
PROFILE_SCOPE("instant death ")
{
cpFloat dist_from_center = cpvlengthsq((entity_pos(e)));
if (e->body != NULL && dist_from_center > (INSTANT_DEATH_DISTANCE_FROM_CENTER * INSTANT_DEATH_DISTANCE_FROM_CENTER))
@ -2457,6 +2486,7 @@ void process(GameState *gs, double dt)
}
// sun processing for this current entity
PROFILE_SCOPE("this entity sun processing")
{
SUNS_ITER(gs)
{
@ -2482,6 +2512,8 @@ void process(GameState *gs, double dt)
}
if (e->is_explosion)
{
PROFILE_SCOPE("Explosion")
{
e->explosion_progress += dt;
e->explosion_pos = cpvadd(e->explosion_pos, cpvmult(e->explosion_vel, dt));
@ -2491,8 +2523,11 @@ void process(GameState *gs, double dt)
entity_destroy(gs, e);
}
}
}
if (e->is_missile)
{
PROFILE_SCOPE("Missile")
{
if (is_burning(e))
{
@ -2510,8 +2545,11 @@ void process(GameState *gs, double dt)
entity_destroy(gs, e);
}
}
}
if (e->is_box)
{
PROFILE_SCOPE("Box processing")
{
if (e->is_platonic)
{
@ -2596,7 +2634,11 @@ void process(GameState *gs, double dt)
grid_remove_box(gs, get_entity(gs, e->shape_parent_entity), e);
}
}
}
if (e->is_grid)
{
PROFILE_SCOPE("Grid processing")
{
Entity *grid = e;
// calculate how much energy solar panels provide
@ -2797,6 +2839,12 @@ void process(GameState *gs, double dt)
}
}
}
}
}
PROFILE_SCOPE("chipmunk physics processing")
{
cpSpaceStep(gs->space, dt);
}
}
}

@ -32,6 +32,9 @@
#define MINIAUDIO_IMPLEMENTATION
#include "miniaudio.h"
#include "ipsettings.h"
#include "profiling.h"
// shaders
#include "goodpixel.gen.h"
#include "hueshift.gen.h"
@ -663,6 +666,7 @@ static void init(void)
ENetEvent event;
enet_address_set_host(&address, SERVER_ADDRESS);
Log("Connecting to %s:%d\n", SERVER_ADDRESS, SERVER_PORT);
address.port = SERVER_PORT;
peer = enet_host_connect(client, &address, 2, 0);
if (peer == NULL)
@ -1385,10 +1389,12 @@ static cpVect get_global_hand_pos(cpVect world_mouse_pos, bool *hand_at_arms_len
return global_hand_pos;
}
static void frame(void)
{
PROFILE_SCOPE("frame")
{
double width = (float)sapp_width(), height = (float)sapp_height();
double ratio = width / height;
double time = sapp_frame_count() * sapp_frame_duration();
double exec_time = sapp_frame_count() * sapp_frame_duration();
double dt = (float)sapp_frame_duration();
// pressed input management
@ -1413,6 +1419,8 @@ static void frame(void)
interact_pressed = mousepressed[SAPP_MOUSEBUTTON_RIGHT].pressed;
// networking
static cpVect before_reprediction = {0};
PROFILE_SCOPE("networking")
{
ENetEvent event;
while (true)
@ -1441,7 +1449,7 @@ static void frame(void)
assert(LZO1X_MEM_DECOMPRESS == 0);
ma_mutex_lock(&play_packets_mutex);
double predicted_to_time = gs.time;
double predicted_to_time = time(&gs);
ServerToClient msg = (ServerToClient){
.cur_gs = &gs,
.audio_playback_buffer = &packets_to_play,
@ -1450,9 +1458,14 @@ static void frame(void)
event.packet->data, event.packet->dataLength, decompressed,
&decompressed_max_len, NULL);
if (return_value == LZO_E_OK)
{
if (myentity() != NULL)
before_reprediction = entity_pos(myentity());
PROFILE_SCOPE("Deserializing data")
{
server_to_client_deserialize(&msg, decompressed,
decompressed_max_len, false);
}
my_player_index = msg.your_player;
}
else
@ -1465,7 +1478,10 @@ static void frame(void)
free(decompressed);
enet_packet_destroy(event.packet);
double server_current_time = gs.time;
PROFILE_SCOPE("Repredicting inputs")
{
double server_current_time = time(&gs);
double difference = predicted_to_time - server_current_time;
double target_prediction_time =
(((double)peer->roundTripTime) / 1000.0) + TIMESTEP * 6.0;
@ -1474,11 +1490,11 @@ static void frame(void)
difference = fmax(difference, target_prediction_time);
double eps = TIMESTEP * 0.1;
if (predicted_to_time - gs.time < target_prediction_time - eps)
if (predicted_to_time - time(&gs) < target_prediction_time - eps)
{
target_prediction_time_factor = 1.1;
}
else if (predicted_to_time - gs.time >
else if (predicted_to_time - time(&gs) >
target_prediction_time + eps * 2.0)
{
target_prediction_time_factor = 0.9;
@ -1490,6 +1506,8 @@ static void frame(void)
// re-predict the inputs
double time_to_repredict = (float)difference;
Log("Repredicting %f\n", time_to_repredict);
uint64_t start_prediction_time = stm_now();
if (time_to_repredict > 0.0)
{
@ -1497,7 +1515,8 @@ static void frame(void)
{
if (stm_ms(stm_diff(stm_now(), start_prediction_time)) > MAX_MS_SPENT_REPREDICTING)
{
Log("Reprediction took longer than %f milliseconds", MAX_MS_SPENT_REPREDICTING);
Log("Reprediction took longer than %f milliseconds, could only predict %f\n", MAX_MS_SPENT_REPREDICTING, time_to_repredict);
break;
}
QUEUE_ITER(&input_queue, cur_header)
{
@ -1508,14 +1527,15 @@ static void frame(void)
break;
}
}
process(&gs, TIMESTEP);
process(&gs, TIMESTEP, false);
time_to_repredict -= TIMESTEP;
}
process(&gs, time_to_repredict);
process(&gs, time_to_repredict, true);
time_to_repredict = 0.0;
}
current_time_ahead_of_server = gs.time - server_current_time;
current_time_ahead_of_server = time(&gs) - server_current_time;
}
break;
}
@ -1539,6 +1559,8 @@ static void frame(void)
}
}
// dbg_rect(before_reprediction);
// gameplay
ui(false, dt, width, height); // if ui button is pressed before game logic, set the pressed to
// false so it doesn't propagate from the UI modal/button
@ -1553,6 +1575,7 @@ static void frame(void)
bool hand_at_arms_length = false;
recalculate_camera_pos();
cpVect world_mouse_pos = screen_to_world(width, height, mouse_pos);
PROFILE_SCOPE("gameplay and prediction")
{
// interpolate zoom
zoom = lerp(zoom, zoom_target, dt * 12.0);
@ -1662,7 +1685,7 @@ static void frame(void)
static double prediction_time_factor = 1.0;
prediction_time_factor = lerp(prediction_time_factor,
target_prediction_time_factor, dt * 3.0);
process(&gs, dt * prediction_time_factor);
process(&gs, dt * prediction_time_factor, true);
static int64_t last_sent_input_time = 0;
if (stm_sec(stm_diff(stm_now(), last_sent_input_time)) >
@ -1725,6 +1748,7 @@ static void frame(void)
}
// drawing
PROFILE_SCOPE("drawing")
{
sgp_begin((int)width, (int)height);
sgp_viewport(0, 0, (int)width, (int)height);
@ -1833,7 +1857,7 @@ static void frame(void)
if (currently_building() != BoxInvalid && can_build(currently_building()))
{
set_color_values(0.5, 0.5, 0.5,
(sin((float)time * 9.0) + 1.0) / 3.0 + 0.2);
(sin((float)exec_time * 9.0) + 1.0) / 3.0 + 0.2);
transform_scope
{
@ -2120,6 +2144,7 @@ static void frame(void)
sg_end_pass();
sg_commit();
}
}
void cleanup(void)
{
@ -2130,6 +2155,9 @@ void cleanup(void)
ma_mutex_unlock(&server_info.info_mutex);
WaitForSingleObject(server_thread_handle, INFINITE);
end_profiling_mythread();
end_profiling();
ma_mutex_uninit(&send_packets_mutex);
ma_mutex_uninit(&play_packets_mutex);
@ -2248,6 +2276,8 @@ sapp_desc sokol_main(int argc, char *argv[])
stm_setup();
ma_mutex_init(&server_info.info_mutex);
server_info.world_save = "debug_world.bin";
init_profiling("astris.spall");
init_profiling_mythread(0);
if (argc > 1)
{
server_thread_handle =

@ -0,0 +1,98 @@
#include "types.h"
#include <stdlib.h> // malloc the profiling buffer
#ifdef PROFILING_H
#error only include profiling.h once
#endif
#define PROFILING_H
#ifdef PROFILING
#define PROFILING_BUFFER_SIZE (1 * 1024 * 1024)
#ifdef PROFILING_IMPL
#define SPALL_IMPLEMENTATION
#pragma warning(disable : 4996) // spall uses fopen
#include "spall.h"
#define WIN32_LEAN_AND_MEAN
#define VC_EXTRALEAN
#define NOMINMAX
#include <Windows.h>
// This is slow, if you can use RDTSC and set the multiplier in SpallInit, you'll have far better timing accuracy
double get_time_in_micros()
{
static double invfreq;
if (!invfreq)
{
LARGE_INTEGER frequency;
QueryPerformanceFrequency(&frequency);
invfreq = 1000000.0 / frequency.QuadPart;
}
LARGE_INTEGER counter;
QueryPerformanceCounter(&counter);
return counter.QuadPart * invfreq;
}
SpallProfile spall_ctx;
THREADLOCAL SpallBuffer spall_buffer;
THREADLOCAL unsigned char *buffer_data = NULL;
THREADLOCAL uint32_t my_thread_id = 0;
void init_profiling(const char *filename)
{
spall_ctx = SpallInit(filename, 1);
}
void init_profiling_mythread(uint32_t id)
{
my_thread_id = id;
if (buffer_data != NULL)
{
*(int *)0 = 0;
}
buffer_data = malloc(PROFILING_BUFFER_SIZE);
spall_buffer = (SpallBuffer){
.length = PROFILING_BUFFER_SIZE,
.data = buffer_data,
};
SpallBufferInit(&spall_ctx, &spall_buffer);
}
void end_profiling_mythread()
{
SpallBufferFlush(&spall_ctx, &spall_buffer);
SpallBufferQuit(&spall_ctx, &spall_buffer);
free(buffer_data);
}
void end_profiling()
{
SpallQuit(&spall_ctx);
}
#endif // PROFILING_IMPL
#include "spall.h"
extern SpallProfile spall_ctx;
extern THREADLOCAL SpallBuffer spall_buffer;
extern THREADLOCAL uint32_t my_thread_id;
double get_time_in_micros();
void init_profiling(const char *filename);
// you can pass anything to id as long as it's different from other threads
void init_profiling_mythread(uint32_t id);
void end_profiling();
void end_profiling_mythread();
#define PROFILE_SCOPE(name) DeferLoop(SpallTraceBeginLenTidPid(&spall_ctx, &spall_buffer, name, sizeof(name) - 1, my_thread_id, 0, get_time_in_micros()), SpallTraceEndTidPid(&spall_ctx, &spall_buffer, my_thread_id, 0, get_time_in_micros()))
#else // PROFILING
void inline init_profiling(const char *filename) { (void)filename; }
// you can pass anything to id as long as it's different from other threads
void inline init_profiling_mythread(uint32_t id) { (void)id; }
void inline end_profiling() {}
void inline end_profiling_mythread() {}
#define PROFILE_SCOPE(name)
#endif

@ -1,5 +1,5 @@
#include "chipmunk.h" // initializing bodies
#include "sokol_time.h"
#include <chipmunk.h> // initializing bodies
#include "types.h"
#include <enet/enet.h>
#include <errno.h>
@ -20,40 +20,7 @@
for (ENetPeer *cur = host->peers; cur < host->peers + host->peerCount; cur++) \
if (cur->state == ENET_PEER_STATE_CONNECTED)
#ifdef PROFILING
#define SPALL_IMPLEMENTATION
#pragma warning(disable : 4996) // spall uses fopen
#include "spall.h"
#define WIN32_LEAN_AND_MEAN
#define VC_EXTRALEAN
#define NOMINMAX
#include <Windows.h>
// This is slow, if you can use RDTSC and set the multiplier in SpallInit, you'll have far better timing accuracy
double get_time_in_micros()
{
static double invfreq;
if (!invfreq)
{
LARGE_INTEGER frequency;
QueryPerformanceFrequency(&frequency);
invfreq = 1000000.0 / frequency.QuadPart;
}
LARGE_INTEGER counter;
QueryPerformanceCounter(&counter);
return counter.QuadPart * invfreq;
}
static SpallProfile spall_ctx;
static SpallBuffer spall_buffer;
#define PROFILE_SCOPE(name) DeferLoop(SpallTraceBeginLenTidPid(&spall_ctx, &spall_buffer, name, sizeof(name) - 1, 0, 0, get_time_in_micros()), SpallTraceEndTidPid(&spall_ctx, &spall_buffer, 0, 0, get_time_in_micros()))
#else // PROFILING
#define PROFILE_SCOPE(name)
#endif
#include "profiling.h"
// started in a thread from host
void server(void *info_raw)
@ -61,14 +28,6 @@ void server(void *info_raw)
ServerThreadInfo *info = (ServerThreadInfo *)info_raw;
const char *world_save_name = info->world_save;
#ifdef PROFILING
#define BUFFER_SIZE (1 * 1024 * 1024)
spall_ctx = SpallInit("server.spall", 1);
unsigned char *buffer = malloc(BUFFER_SIZE);
spall_buffer = (SpallBuffer){
.length = BUFFER_SIZE,
.data = buffer,
};
SpallBufferInit(&spall_ctx, &spall_buffer);
#endif
@ -79,6 +38,8 @@ void server(void *info_raw)
gs.server_side_computing = true;
Log("Allocated %zu bytes for entities\n", entities_size);
init_profiling_mythread(1);
create_initial_world(&gs);
// inputs
@ -199,6 +160,8 @@ void server(void *info_raw)
double audio_time_to_send = 0.0;
double total_time = 0.0;
unsigned char *world_save_buffer = malloc(entities_size);
PROFILE_SCOPE("Serving")
{
while (true)
{
ma_mutex_lock(&info->info_mutex);
@ -344,9 +307,9 @@ void server(void *info_raw)
total_time = max_time;
}
PROFILE_SCOPE("World Processing")
{
while (total_time > TIMESTEP)
{
PROFILE_SCOPE("World Processing")
{
CONNECTED_PEERS(enet_host, cur)
{
@ -362,7 +325,7 @@ void server(void *info_raw)
}
}
process(&gs, TIMESTEP);
process(&gs, TIMESTEP, false);
total_time -= TIMESTEP;
}
}
@ -530,6 +493,7 @@ void server(void *info_raw)
}
}
}
}
for (int i = 0; i < MAX_PLAYERS; i++)
{
if (player_encoders[i] != NULL)
@ -547,10 +511,9 @@ void server(void *info_raw)
enet_host_destroy(enet_host);
enet_deinitialize();
end_profiling_mythread();
printf("Cleanup\n");
#ifdef PROFILING
SpallBufferQuit(&spall_ctx, &spall_buffer);
SpallQuit(&spall_ctx);
#endif
}

Binary file not shown.

@ -337,7 +337,9 @@ typedef struct GameState
// @Robust for the integer tick, also store a double for how much time has been processed.
// Like a whole timestep then a double for subtimestep
double time; // @Robust separate tick integer not prone to precision issues. Could be very large as is saved to disk!
uint64_t tick;
double subframe_time;
cpVect goldpos;
@ -421,9 +423,12 @@ void create_initial_world(GameState *gs);
void initialize(struct GameState *gs, void *entity_arena, size_t entity_arena_size);
void destroy(struct GameState *gs);
void process_fixed_timestep(GameState *gs);
void process(struct GameState *gs, double dt); // does in place
// if is subframe, doesn't always increment the tick. When enough
// subframe time has been processed, increments the tick
void process(struct GameState *gs, double dt, bool is_subframe); // does in place
Entity *closest_box_to_point_in_radius(struct GameState *gs, cpVect point, double radius, bool (*filter_func)(Entity *));
uint64_t tick(struct GameState *gs);
double time(GameState *gs);
double sun_dist_no_gravity(Entity *sun);
// all of these return if successful or not

Loading…
Cancel
Save