static void PRVM_CallProfile (prvm_prog_t *prog) { mfunction_t *f, *best; int i; double max; double sum; double newprofiletime; Con_Printf( "%s Call Profile:\n", prog->name ); sum = 0; do { max = 0; best = NULL; for (i=0 ; i<prog->numfunctions ; i++) { f = &prog->functions[i]; if (max < f->totaltime) { max = f->totaltime; best = f; } } if (best) { sum += best->totaltime; Con_Printf("%9.4f %s\n", best->totaltime, PRVM_GetString(prog, best->s_name)); best->totaltime = 0; } } while (best); newprofiletime = Sys_DirtyTime(); Con_Printf("Total time since last profile reset: %9.4f\n", newprofiletime - prog->profiletime); Con_Printf(" - used by QC code of this VM: %9.4f\n", sum); prog->profiletime = newprofiletime; }
void Host_Main(void) { double time1 = 0; double time2 = 0; double time3 = 0; double cl_timer = 0, sv_timer = 0; double clframetime, deltacleantime, olddirtytime, dirtytime; double wait; int pass1, pass2, pass3, i; char vabuf[1024]; qboolean playing; Host_Init(); realtime = 0; host_dirtytime = Sys_DirtyTime(); for (;;) { if (setjmp(host_abortframe)) { SCR_ClearLoadingScreen(false); continue; // something bad happened, or the server disconnected } olddirtytime = host_dirtytime; dirtytime = Sys_DirtyTime(); deltacleantime = dirtytime - olddirtytime; if (deltacleantime < 0) { // warn if it's significant if (deltacleantime < -0.01) Con_Printf("Host_Mingled: time stepped backwards (went from %f to %f, difference %f)\n", olddirtytime, dirtytime, deltacleantime); deltacleantime = 0; } else if (deltacleantime >= 1800) { Con_Printf("Host_Mingled: time stepped forward (went from %f to %f, difference %f)\n", olddirtytime, dirtytime, deltacleantime); deltacleantime = 0; } realtime += deltacleantime; host_dirtytime = dirtytime; cl_timer += deltacleantime; sv_timer += deltacleantime; if (!svs.threaded) { svs.perf_acc_realtime += deltacleantime; // Look for clients who have spawned playing = false; for (i = 0, host_client = svs.clients;i < svs.maxclients;i++, host_client++) if(host_client->begun) if(host_client->netconnection) playing = true; if(sv.time < 10) { // don't accumulate time for the first 10 seconds of a match // so things can settle svs.perf_acc_realtime = svs.perf_acc_sleeptime = svs.perf_acc_lost = svs.perf_acc_offset = svs.perf_acc_offset_squared = svs.perf_acc_offset_max = svs.perf_acc_offset_samples = 0; } else if(svs.perf_acc_realtime > 5) { svs.perf_cpuload = 1 - svs.perf_acc_sleeptime / svs.perf_acc_realtime; svs.perf_lost = svs.perf_acc_lost / svs.perf_acc_realtime; if(svs.perf_acc_offset_samples > 0) { svs.perf_offset_max = svs.perf_acc_offset_max; svs.perf_offset_avg = svs.perf_acc_offset / svs.perf_acc_offset_samples; svs.perf_offset_sdev = sqrt(svs.perf_acc_offset_squared / svs.perf_acc_offset_samples - svs.perf_offset_avg * svs.perf_offset_avg); } if(svs.perf_lost > 0 && developer_extra.integer) if(playing) // only complain if anyone is looking Con_DPrintf("Server can't keep up: %s\n", Host_TimingReport(vabuf, sizeof(vabuf))); svs.perf_acc_realtime = svs.perf_acc_sleeptime = svs.perf_acc_lost = svs.perf_acc_offset = svs.perf_acc_offset_squared = svs.perf_acc_offset_max = svs.perf_acc_offset_samples = 0; } } if (slowmo.value < 0.00001 && slowmo.value != 0) Cvar_SetValue("slowmo", 0); if (host_framerate.value < 0.00001 && host_framerate.value != 0) Cvar_SetValue("host_framerate", 0); // keep the random time dependent, but not when playing demos/benchmarking if(!*sv_random_seed.string && !cls.demoplayback) rand(); // get new key events Key_EventQueue_Unblock(); SndSys_SendKeyEvents(); Sys_SendKeyEvents(); NetConn_UpdateSockets(); Log_DestBuffer_Flush(); // receive packets on each main loop iteration, as the main loop may // be undersleeping due to select() detecting a new packet if (sv.active && !svs.threaded) NetConn_ServerFrame(); Curl_Run(); // check for commands typed to the host Host_GetConsoleCommands(); // when a server is running we only execute console commands on server frames // (this mainly allows frikbot .way config files to work properly by staying in sync with the server qc) // otherwise we execute them on client frames if (sv.active ? sv_timer > 0 : cl_timer > 0) { // process console commands // R_TimeReport("preconsole"); CL_VM_PreventInformationLeaks(); Cbuf_Frame(); // R_TimeReport("console"); } //Con_Printf("%6.0f %6.0f\n", cl_timer * 1000000.0, sv_timer * 1000000.0); // if the accumulators haven't become positive yet, wait a while if (cls.state == ca_dedicated) wait = sv_timer * -1000000.0; else if (!sv.active || svs.threaded) wait = cl_timer * -1000000.0; else wait = max(cl_timer, sv_timer) * -1000000.0; if (!cls.timedemo && wait >= 1) { double time0, delta; if(host_maxwait.value <= 0) wait = min(wait, 1000000.0); else wait = min(wait, host_maxwait.value * 1000.0); if(wait < 1) wait = 1; // because we cast to int time0 = Sys_DirtyTime(); if (sv_checkforpacketsduringsleep.integer && !sys_usenoclockbutbenchmark.integer && !svs.threaded) { NetConn_SleepMicroseconds((int)wait); if (cls.state != ca_dedicated) NetConn_ClientFrame(); // helps server browser get good ping values // TODO can we do the same for ServerFrame? Probably not. } else Sys_Sleep((int)wait); delta = Sys_DirtyTime() - time0; if (delta < 0 || delta >= 1800) delta = 0; if (!svs.threaded) svs.perf_acc_sleeptime += delta; // R_TimeReport("sleep"); continue; } // limit the frametime steps to no more than 100ms each if (cl_timer > 0.1) cl_timer = 0.1; if (sv_timer > 0.1) { if (!svs.threaded) svs.perf_acc_lost += (sv_timer - 0.1); sv_timer = 0.1; } R_TimeReport("---"); //------------------- // // server operations // //------------------- // limit the frametime steps to no more than 100ms each if (sv.active && sv_timer > 0 && !svs.threaded) { // execute one or more server frames, with an upper limit on how much // execution time to spend on server frames to avoid freezing the game if // the server is overloaded, this execution time limit means the game will // slow down if the server is taking too long. int framecount, framelimit = 1; double advancetime, aborttime = 0; float offset; prvm_prog_t *prog = SVVM_prog; // run the world state // don't allow simulation to run too fast or too slow or logic glitches can occur // stop running server frames if the wall time reaches this value if (sys_ticrate.value <= 0) advancetime = sv_timer; else if (cl.islocalgame && !sv_fixedframeratesingleplayer.integer) { // synchronize to the client frametime, but no less than 10ms and no more than 100ms advancetime = bound(0.01, cl_timer, 0.1); } else { advancetime = sys_ticrate.value; // listen servers can run multiple server frames per client frame framelimit = cl_maxphysicsframesperserverframe.integer; aborttime = Sys_DirtyTime() + 0.1; } if(slowmo.value > 0 && slowmo.value < 1) advancetime = min(advancetime, 0.1 / slowmo.value); else advancetime = min(advancetime, 0.1); if(advancetime > 0) { offset = Sys_DirtyTime() - dirtytime;if (offset < 0 || offset >= 1800) offset = 0; offset += sv_timer; ++svs.perf_acc_offset_samples; svs.perf_acc_offset += offset; svs.perf_acc_offset_squared += offset * offset; if(svs.perf_acc_offset_max < offset) svs.perf_acc_offset_max = offset; } // only advance time if not paused // the game also pauses in singleplayer when menu or console is used sv.frametime = advancetime * slowmo.value; if (host_framerate.value) sv.frametime = host_framerate.value; if (sv.paused || (cl.islocalgame && (key_dest != key_game || key_consoleactive || cl.csqc_paused))) sv.frametime = 0; for (framecount = 0;framecount < framelimit && sv_timer > 0;framecount++) { sv_timer -= advancetime; // move things around and think unless paused if (sv.frametime) SV_Physics(); // if this server frame took too long, break out of the loop if (framelimit > 1 && Sys_DirtyTime() >= aborttime) break; } R_TimeReport("serverphysics"); // send all messages to the clients SV_SendClientMessages(); if (sv.paused == 1 && realtime > sv.pausedstart && sv.pausedstart > 0) { prog->globals.fp[OFS_PARM0] = realtime - sv.pausedstart; PRVM_serverglobalfloat(time) = sv.time; prog->ExecuteProgram(prog, PRVM_serverfunction(SV_PausedTic), "QC function SV_PausedTic is missing"); } // send an heartbeat if enough time has passed since the last one NetConn_Heartbeat(0); R_TimeReport("servernetwork"); } else if (!svs.threaded) { // don't let r_speeds display jump around R_TimeReport("serverphysics"); R_TimeReport("servernetwork"); } //------------------- // // client operations // //------------------- if (cls.state != ca_dedicated && (cl_timer > 0 || cls.timedemo || ((vid_activewindow ? cl_maxfps : cl_maxidlefps).value < 1))) { R_TimeReport("---"); Collision_Cache_NewFrame(); R_TimeReport("photoncache"); // decide the simulation time if (cls.capturevideo.active) { //*** if (cls.capturevideo.realtime) clframetime = cl.realframetime = max(cl_timer, 1.0 / cls.capturevideo.framerate); else { clframetime = 1.0 / cls.capturevideo.framerate; cl.realframetime = max(cl_timer, clframetime); } } else if (vid_activewindow && cl_maxfps.value >= 1 && !cls.timedemo) { clframetime = cl.realframetime = max(cl_timer, 1.0 / cl_maxfps.value); // when running slow, we need to sleep to keep input responsive wait = bound(0, cl_maxfps_alwayssleep.value * 1000, 100000); if (wait > 0) Sys_Sleep((int)wait); } else if (!vid_activewindow && cl_maxidlefps.value >= 1 && !cls.timedemo) clframetime = cl.realframetime = max(cl_timer, 1.0 / cl_maxidlefps.value); else clframetime = cl.realframetime = cl_timer; // apply slowmo scaling clframetime *= cl.movevars_timescale; // scale playback speed of demos by slowmo cvar if (cls.demoplayback) { clframetime *= slowmo.value; // if demo playback is paused, don't advance time at all if (cls.demopaused) clframetime = 0; } else { // host_framerate overrides all else if (host_framerate.value) clframetime = host_framerate.value; if (cl.paused || (cl.islocalgame && (key_dest != key_game || key_consoleactive || cl.csqc_paused))) clframetime = 0; } if (cls.timedemo) clframetime = cl.realframetime = cl_timer; // deduct the frame time from the accumulator cl_timer -= cl.realframetime; cl.oldtime = cl.time; cl.time += clframetime; // update video if (host_speeds.integer) time1 = Sys_DirtyTime(); R_TimeReport("pre-input"); // Collect input into cmd CL_Input(); R_TimeReport("input"); // check for new packets NetConn_ClientFrame(); // read a new frame from a demo if needed CL_ReadDemoMessage(); R_TimeReport("clientnetwork"); // now that packets have been read, send input to server CL_SendMove(); R_TimeReport("sendmove"); // update client world (interpolate entities, create trails, etc) CL_UpdateWorld(); R_TimeReport("lerpworld"); CL_Video_Frame(); R_TimeReport("client"); CL_UpdateScreen(); CL_MeshEntities_Reset(); R_TimeReport("render"); if (host_speeds.integer) time2 = Sys_DirtyTime(); // update audio if(cl.csqc_usecsqclistener) { S_Update(&cl.csqc_listenermatrix); cl.csqc_usecsqclistener = false; } else S_Update(&r_refdef.view.matrix); CDAudio_Update(); R_TimeReport("audio"); // reset gathering of mouse input in_mouse_x = in_mouse_y = 0; if (host_speeds.integer) { pass1 = (int)((time1 - time3)*1000000); time3 = Sys_DirtyTime(); pass2 = (int)((time2 - time1)*1000000); pass3 = (int)((time3 - time2)*1000000); Con_Printf("%6ius total %6ius server %6ius gfx %6ius snd\n", pass1+pass2+pass3, pass1, pass2, pass3); } } #if MEMPARANOIA Mem_CheckSentinelsGlobal(); #else if (developer_memorydebug.integer) Mem_CheckSentinelsGlobal(); #endif // if there is some time remaining from this frame, reset the timers if (cl_timer >= 0) cl_timer = 0; if (sv_timer >= 0) { if (!svs.threaded) svs.perf_acc_lost += sv_timer; sv_timer = 0; } host_framecount++; } }
void PRVM_ExecuteProgram (prvm_prog_t *prog, func_t fnum, const char *errormessage) #endif { mstatement_t *st, *startst; mfunction_t *func, *enterfunc; prvm_edict_t *ed; prvm_eval_t *ptr; int jumpcount, cachedpr_trace, exitdepth; int restorevm_tempstringsbuf_cursize; double calltime; double tm, starttm; prvm_vec_t tempfloat; // these may become out of date when a builtin is called, and are updated accordingly prvm_vec_t *cached_edictsfields = prog->edictsfields; unsigned int cached_entityfields = prog->entityfields; unsigned int cached_entityfields_3 = prog->entityfields - 3; unsigned int cached_entityfieldsarea = prog->entityfieldsarea; unsigned int cached_entityfieldsarea_entityfields = prog->entityfieldsarea - prog->entityfields; unsigned int cached_entityfieldsarea_3 = prog->entityfieldsarea - 3; unsigned int cached_entityfieldsarea_entityfields_3 = prog->entityfieldsarea - prog->entityfields - 3; unsigned int cached_max_edicts = prog->max_edicts; // these do not change mstatement_t *cached_statements = prog->statements; qboolean cached_allowworldwrites = prog->allowworldwrites; unsigned int cached_flag = prog->flag; calltime = Sys_DirtyTime(); if (!fnum || fnum >= (unsigned int)prog->numfunctions) { if (PRVM_allglobaledict(self)) PRVM_ED_Print(prog, PRVM_PROG_TO_EDICT(PRVM_allglobaledict(self)), NULL); prog->error_cmd("SVVM_ExecuteProgram: %s", errormessage); } func = &prog->functions[fnum]; // after executing this function, delete all tempstrings it created restorevm_tempstringsbuf_cursize = prog->tempstringsbuf.cursize; prog->trace = prvm_traceqc.integer; // we know we're done when pr_depth drops to this exitdepth = prog->depth; // make a stack frame st = &prog->statements[PRVM_EnterFunction(prog, func)]; // save the starting statement pointer for profiling // (when the function exits or jumps, the (st - startst) integer value is // added to the function's profile counter) startst = st; starttm = calltime; // instead of counting instructions, we count jumps jumpcount = 0; // add one to the callcount of this function because otherwise engine-called functions aren't counted if (prog->xfunction->callcount++ == 0 && (prvm_coverage.integer & 1)) PRVM_FunctionCoverageEvent(prog, prog->xfunction); chooseexecprogram: cachedpr_trace = prog->trace; if (prog->trace || prog->watch_global_type != ev_void || prog->watch_field_type != ev_void || prog->break_statement >= 0) { #define PRVMSLOWINTERPRETER 1 if (prvm_timeprofiling.integer) { #define PRVMTIMEPROFILING 1 #include "prvm_execprogram.h" #undef PRVMTIMEPROFILING } else { #include "prvm_execprogram.h" } #undef PRVMSLOWINTERPRETER } else { if (prvm_timeprofiling.integer) { #define PRVMTIMEPROFILING 1 #include "prvm_execprogram.h" #undef PRVMTIMEPROFILING } else { #include "prvm_execprogram.h" } } cleanup: if (developer_insane.integer && prog->tempstringsbuf.cursize > restorevm_tempstringsbuf_cursize) Con_DPrintf("SVVM_ExecuteProgram: %s used %i bytes of tempstrings\n", PRVM_GetString(prog, prog->functions[fnum].s_name), prog->tempstringsbuf.cursize - restorevm_tempstringsbuf_cursize); // delete tempstrings created by this function prog->tempstringsbuf.cursize = restorevm_tempstringsbuf_cursize; tm = Sys_DirtyTime() - calltime; if (tm < 0 || tm >= 1800) tm = 0; func->totaltime += tm; if (prog == SVVM_prog) SV_FlushBroadcastMessages(); }