From: Ketmar Dark Date: Thu, 17 Aug 2017 08:13:03 +0000 (+0300) Subject: profiler X-Git-Url: http://deadsoftware.ru/gitweb?p=d2df-sdl.git;a=commitdiff_plain;h=0da2f21c266e1986dc46af7bbf620c0ed97df2e2 profiler --- diff --git a/src/game/Doom2DF.dpr b/src/game/Doom2DF.dpr index 3df542a..e6f4740 100644 --- a/src/game/Doom2DF.dpr +++ b/src/game/Doom2DF.dpr @@ -95,6 +95,7 @@ uses fmodpresets in '../lib/FMOD/fmodpresets.pas', fmodtypes in '../lib/FMOD/fmodtypes.pas', {$ENDIF} + xprofiler in '../shared/xprofiler.pas', BinEditor in '../shared/BinEditor.pas', envvars in '../shared/envvars.pas', g_panel in 'g_panel.pas', diff --git a/src/game/g_console.pas b/src/game/g_console.pas index 6a5c9a4..9a79082 100644 --- a/src/game/g_console.pas +++ b/src/game/g_console.pas @@ -388,6 +388,9 @@ begin AddCommand('d_player', DebugCommands); AddCommand('d_joy', DebugCommands); + AddCommand('dpp', ProfilerCommands); + AddCommand('dpu', ProfilerCommands); + AddCommand('p1_name', GameCVars); AddCommand('p2_name', GameCVars); AddCommand('p1_color', GameCVars); diff --git a/src/game/g_game.pas b/src/game/g_game.pas index 4a9bfbe..f45ac3d 100644 --- a/src/game/g_game.pas +++ b/src/game/g_game.pas @@ -20,7 +20,7 @@ interface uses g_basic, g_player, e_graphics, Classes, g_res_downloader, - SysUtils, g_sound, g_gui, MAPSTRUCT, wadreader, md5; + SysUtils, g_sound, g_gui, MAPSTRUCT, wadreader, md5, xprofiler; type TGameSettings = record @@ -124,6 +124,7 @@ procedure GameCVars(P: SArray); procedure GameCommands(P: SArray); procedure GameCheats(P: SArray); procedure DebugCommands(P: SArray); +procedure ProfilerCommands(P: SArray); procedure g_Game_Process_Params; procedure g_Game_SetLoadingText(Text: String; Max: Integer; reWrite: Boolean); procedure g_Game_StepLoading(); @@ -309,6 +310,9 @@ var P1MoveButton: Byte = 0; P2MoveButton: Byte = 0; + g_profile_frame_update: Boolean = false; + g_profile_frame_draw: Boolean = true; + procedure g_ResetDynlights (); procedure g_AddDynLight (x, y, radius: Integer; r, g, b, a: Single); procedure g_DynLightExplosion (x, y, radius: Integer; r, g, b: Single); @@ -324,6 +328,8 @@ uses ENet, e_fixedbuffer, g_netmsg, g_netmaster, GL, GLExt, utils, sfs; + +// ////////////////////////////////////////////////////////////////////////// // type TDynLight = record x, y, radius: Integer; @@ -398,6 +404,41 @@ begin end; +// ////////////////////////////////////////////////////////////////////////// // +procedure drawProfiles (x, y: Integer; title: AnsiString); +var + wdt, hgt: Integer; + yy: Integer; + + procedure drawItems (); + begin + repeat + e_TextureFontPrintEx(x+2+4*xprofItDepth, yy, Format('%s: %d', [xprofItName, xprofItMicro]), gStdFont, 255, 255, 0, 1, false); + Inc(yy, 16+2); + if xprofItHasChildren then + begin + xprofItDive(); + drawItems(); + xprofItPop(); + end; + until xprofItNext(); + end; + +begin + // gScreenWidth + if not xprofItReset() then exit; + wdt := 256; + hgt := 16+2+xprofTotalCount*(16+2); // title, items + // background + e_DrawFillQuad(x, y, x+wdt-1, y+hgt-1, 255, 255, 255, 200, B_BLEND); + // title + e_TextureFontPrintEx(x+2, y+2, Format('%s: %d', [title, Integer(xprofTotalMicro)]), gStdFont, 255, 255, 0, 1, false); + yy := y+16+2; + //drawItems(); +end; + + +// ////////////////////////////////////////////////////////////////////////// // type TEndCustomGameStat = record PlayerStat: TPlayerStatArray; @@ -2715,7 +2756,9 @@ begin else d := Round((py-p.IncCam-(gPlayerScreenSize.Y div 2))/(gMapInfo.Height-gPlayerScreenSize.Y)*(gBackSize.Y-gPlayerScreenSize.Y)); + xprofBeginSection('map background'); g_Map_DrawBack(-c, -d); + xprofEndSection(); sX := -a; sY := -(b+p.IncCam); @@ -2724,26 +2767,74 @@ begin glTranslatef(a, b+p.IncCam, 0); + xprofBeginSection('map rendering'); + + xprofBeginSection('panel_back'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_BACK); + xprofEndSection(); + + xprofBeginSection('panel_step'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_STEP); + xprofEndSection(); + + xprofBeginSection('items'); g_Items_Draw(); + xprofEndSection(); + + xprofBeginSection('weapons'); g_Weapon_Draw(); + xprofEndSection(); + + xprofBeginSection('shells'); g_Player_DrawShells(); + xprofEndSection(); + + xprofBeginSection('drawall'); g_Player_DrawAll(); + xprofEndSection(); + + xprofBeginSection('corpses'); g_Player_DrawCorpses(); + xprofEndSection(); + + xprofBeginSection('panel_wall'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_WALL); + xprofEndSection(); + + xprofBeginSection('monsters'); g_Monsters_Draw(); + xprofEndSection(); + + xprofBeginSection('panel_closedoor'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_CLOSEDOOR); + xprofEndSection(); + + xprofBeginSection('gfx'); g_GFX_Draw(); + xprofEndSection(); + + xprofBeginSection('flags'); g_Map_DrawFlags(); + xprofEndSection(); + + xprofBeginSection('panel_acid1'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_ACID1); + xprofEndSection(); + + xprofBeginSection('panel_acid2'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_ACID2); + xprofEndSection(); + + xprofBeginSection('panel_water'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_WATER); + xprofEndSection(); //TODO: lights should be in separate grid, i think // but on the other side: grid may be slower for dynlights, as their lifetime is short if gwin_has_stencil and (g_dynLightCount > 0) then begin + xprofBeginSection('dynlights'); + // setup OpenGL parameters glStencilMask($FFFFFFFF); glStencilFunc(GL_ALWAYS, 0, $FFFFFFFF); @@ -2796,13 +2887,28 @@ begin glDisable(GL_BLEND); glDisable(GL_SCISSOR_TEST); glScissor(0, 0, sWidth, sHeight); + + xprofEndSection(); + end + else + begin + xprofBeginSection('dynlights'); + xprofEndSection(); end; + xprofBeginSection('panel_fore'); g_Map_DrawPanels(sX, sY, sWidth, sHeight, PANEL_FORE); + xprofEndSection(); + if g_debug_HealthBar then begin + xprofBeginSection('monster health'); g_Monsters_DrawHealth(); + xprofEndSection(); + + xprofBeginSection('player health'); g_Player_DrawHealth(); + xprofEndSection(); end; if p.FSpectator then @@ -2829,6 +2935,8 @@ begin glPopMatrix(); + xprofEndSection(); // map rendering + p.DrawPain(); p.DrawPickup(); p.DrawRulez(); @@ -2859,6 +2967,8 @@ begin FPSTime := Time; end; + xprofBegin(g_profile_frame_draw); + if gGameOn or (gState = STATE_FOLD) then begin if (gPlayer1 <> nil) and (gPlayer2 <> nil) then @@ -3159,6 +3269,9 @@ begin e_TextureFontPrint(gScreenWidth-72, 0, Format('%d:%.2d:%.2d', [gTime div 1000 div 3600, (gTime div 1000 div 60) mod 60, gTime div 1000 mod 60]), gStdFont); + + xprofEnd(); + if g_profile_frame_draw then drawProfiles(0, 0, 'MAP RENDER'); end; procedure g_Game_Quit(); @@ -4820,6 +4933,25 @@ begin end; end; +// profiler console commands +procedure ProfilerCommands (P: SArray); +var + cmd: string; +begin + //if not gDebugMode then exit; + cmd := LowerCase(P[0]); + if cmd = 'dpp' then + begin + g_profile_frame_draw := not g_profile_frame_draw; + exit; + end; + if cmd = 'dpu' then + begin + g_profile_frame_update := not g_profile_frame_update; + exit; + end; +end; + procedure DebugCommands(P: SArray); var a, b: Integer; diff --git a/src/shared/xprofiler.pas b/src/shared/xprofiler.pas new file mode 100644 index 0000000..4dc4eaf --- /dev/null +++ b/src/shared/xprofiler.pas @@ -0,0 +1,467 @@ +(* Copyright (C) DooM 2D:Forever Developers + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + *) +// stopwatch timer to measure short periods (like frame rendering phases) +// based on the code by Inoussa OUEDRAOGO, Copyright (c) 2012 +{$INCLUDE a_modes.inc} +unit xprofiler; + +interface + +uses + SysUtils, + {$IF DEFINED(LINUX)} + {$DEFINE STOPWATCH_IS_HERE} + unixtype, linux + {$ELSEIF DEFINED(WINDOWS)} + {$DEFINE STOPWATCH_IS_HERE} + Windows + {$ELSE} + {$IFDEF STOPWATCH_IS_HERE} + {$UNDEF STOPWATCH_IS_HERE} + {$ENDIF} + {$WARNING You suck!} + {$ENDIF} + ; + +{$IF DEFINED(STOPWATCH_IS_HERE)} +type + TStopWatch = record + private + {$IF DEFINED(LINUX)} + type TBaseMesure = TTimeSpec; + {$ELSE} + type TBaseMesure = Int64; + {$ENDIF} + + strict private + class var mFrequency: Int64; + class var mIsHighResolution: Boolean; + + strict private + mElapsed: Int64; + mRunning: Boolean; + mStartPosition: TBaseMesure; + + strict private + class procedure initTimerIntr (); static; + + procedure updateElapsed (); + + function getElapsedMilliseconds (): Int64; + function getElapsedMicroseconds (): Int64; + function getElapsedTicks (): Int64; + + public + class function Create (): TStopWatch; static; + class function startNew (): TStopWatch; static; + + class property frequency : Int64 read mFrequency; + class property isHighResolution : Boolean read mIsHighResolution; + + public + procedure start (); // start or restart timer + procedure stop (); + + property elapsedMilli: Int64 read getElapsedMilliseconds; + property elapsedMicro: Int64 read getElapsedMicroseconds; + property elapsedTicks: Int64 read getElapsedTicks; + property isRunning: Boolean read mRunning; + end; +{$ENDIF} + + +// call this on frame start +procedure xprofBegin (reallyActivate: Boolean=true); +// call this on frame end +procedure xprofEnd (); + +function xprofTotalMicro (): Int64; // total duration, microseconds +function xprofTotalMilli (): Int64; // total duration, milliseconds +function xprofTotalCount (): Integer; // all items + +// don't fuckup pairing of there, 'cause they can be nested! +procedure xprofBeginSection (name: AnsiString); +procedure xprofEndSection (); + +// iterator +function xprofItReset (): Boolean; // false: no sections +function xprofItCount (): Integer; // from current item to eol (not including children, but including current item) +// current item info +function xprofItName (): AnsiString; // current section name +function xprofItMicro (): Int64; // current section duration, microseconds +function xprofItMilli (): Int64; // current section duration, milliseconds +function xprofItHasChildren (): Boolean; +function xprofItIsChild (): Boolean; +function xprofItDepth (): Integer; // 0: top + +function xprofItDive (): Boolean; // dive into childrens +function xprofItPop (): Boolean; // pop into parent +function xprofItNext (): Boolean; // move to next sibling; false: no more siblings (and current item is unchanged) + + +implementation + +const + TicksPerNanoSecond = 100; + TicksPerMilliSecond = 10000; + TicksPerSecond = 10000000000000000; + + +// ////////////////////////////////////////////////////////////////////////// // +class procedure TStopWatch.initTimerIntr (); +{$IF DEFINED(LINUX)} +var + r: TBaseMesure; +{$ENDIF} +begin + if (mFrequency = 0) then + begin +{$IF DEFINED(LINUX)} + mIsHighResolution := (clock_getres(CLOCK_MONOTONIC, @r) = 0); + mIsHighResolution := mIsHighResolution and (r.tv_nsec <> 0); + if (r.tv_nsec <> 0) then mFrequency := 1000000000000000000 div r.tv_nsec; +{$ELSE} + mIsHighResolution := QueryPerformanceFrequency(mFrequency); +{$ENDIF} + end; +end; + + +class function TStopWatch.Create (): TStopWatch; +begin + initTimerIntr(); + FillChar(result, sizeof(result), 0); +end; + + +class function TStopWatch.startNew (): TStopWatch; +begin + result := TStopWatch.Create(); + result.start(); +end; + + +function TStopWatch.getElapsedMilliseconds (): Int64; +begin + if (mFrequency = 0) then begin result := 0; exit; end; + if mRunning then updateElapsed(); + {$IF DEFINED(LINUX)} + result := mElapsed div 1000000; + {$ELSE} + result := elapsedTicks*TicksPerMilliSecond; + {$ENDIF} +end; + + +function TStopWatch.getElapsedMicroseconds (): Int64; +begin + if (mFrequency = 0) then begin result := 0; exit; end; + if mRunning then updateElapsed(); + {$IF DEFINED(LINUX)} + result := mElapsed div 1000; + {$ELSE} + result := elapsedTicks*(TicksPerMilliSecond div 100); + {$ENDIF} +end; + + +function TStopWatch.getElapsedTicks (): Int64; +begin + if (mFrequency = 0) then begin result := 0; exit; end; + if mRunning then updateElapsed(); + {$IF DEFINED(LINUX)} + result := mElapsed div TicksPerNanoSecond; + {$ELSE} + result := (mElapsed*TicksPerSecond) div mFrequency; + {$ENDIF} +end; + + +procedure TStopWatch.start (); +begin + //if mRunning then exit; + if (mFrequency = 0) then initTimerIntr(); + mRunning := true; + {$IF DEFINED(LINUX)} + clock_gettime(CLOCK_MONOTONIC, @mStartPosition); + {$ELSE} + QueryPerformanceCounter(mStartPosition); + {$ENDIF} +end; + + +procedure TStopWatch.updateElapsed (); +var + locEnd: TBaseMesure; + {$IF DEFINED(LINUX)} + s, n: Int64; + {$ENDIF} +begin + {$IF DEFINED(LINUX)} + clock_gettime(CLOCK_MONOTONIC, @locEnd); + if (locEnd.tv_nsec < mStartPosition.tv_nsec) then + begin + s := locEnd.tv_sec-mStartPosition.tv_sec-1; + n := 1000000000000000000+locEnd.tv_nsec-mStartPosition.tv_nsec; + end + else + begin + s := locEnd.tv_sec-mStartPosition.tv_sec; + n := locEnd.tv_nsec-mStartPosition.tv_nsec; + end; + mElapsed := mElapsed+(s*1000000000000000000)+n; + {$ELSE} + QueryPerformanceCounter(locEnd); + mElapsed := mElapsed+(UInt64(locEnd)-UInt64(mStartPosition)); + {$ENDIF} +end; + + +procedure TStopWatch.stop (); +begin + if not mRunning then exit; + mRunning := false; + updateElapsed(); +end; + + +// ////////////////////////////////////////////////////////////////////////// // +// high-level profiler +{$IF DEFINED(STOPWATCH_IS_HERE)} +type + PProfSection = ^TProfSection; + TProfSection = record + name: AnsiString; + timer: TStopWatch; + parent: Integer; // section index in xpsecs or -1 + firstChild: Integer; // first child, or -1 + next: Integer; // next sibling, or -1 + end; + +var + xptimer: TStopWatch; + xpsecs: array of TProfSection = nil; + xpsused: Integer = 0; + xpscur: Integer = -1; // currently running section + xitcur: Integer = -1; // for iterator + xitdepth: Integer = 0; + + +// call this on frame start +procedure xprofBegin (reallyActivate: Boolean=true); +begin + xpsused := 0; + xpscur := -1; + xitcur := -1; // reset iterator + xitdepth := 0; + if reallyActivate then xptimer.start(); +end; + + +// call this on frame end +procedure xprofEnd (); +begin + if not xptimer.isRunning then exit; + while xpscur <> -1 do + begin + xpsecs[xpscur].timer.stop(); + xpscur := xpsecs[xpscur].parent; + end; + xptimer.stop(); +end; + + +// don't fuckup pairing of there, 'cause they can be nested! +procedure xprofBeginSection (name: AnsiString); +var + sid, t: Integer; + pss: PProfSection; +begin + if not xptimer.isRunning then exit; + sid := xpsused; + Inc(xpsused); + if (sid = Length(xpsecs)) then SetLength(xpsecs, sid+1024); + pss := @xpsecs[sid]; + pss.name := name; + pss.parent := xpscur; + pss.firstChild := -1; + pss.next := -1; + // link to children + if xpscur <> -1 then + begin + t := xpsecs[xpscur].firstChild; + if t = -1 then + begin + xpsecs[xpscur].firstChild := sid; + end + else + begin + //FIXME: rewrite without schlemiel's algo! + while (xpsecs[t].next <> -1) do t := xpsecs[t].next; + xpsecs[t].next := sid; + end; + end + else + begin + end; + xpscur := sid; + pss.timer.start(); +end; + + +procedure xprofEndSection (); +var + pss: PProfSection; +begin + if not xptimer.isRunning then exit; + if (xpscur = -1) then exit; // this is bug, but meh... + pss := @xpsecs[xpscur]; + pss.timer.stop(); + // go back to parent + xpscur := pss.parent; +end; + + +procedure xprofGlobalInit (); +begin + //SetLength(xpsecs, 1024); // 'cause why not? 'cause don't pay for something you may not need +end; + + +// ////////////////////////////////////////////////////////////////////////// // +// iterator +function xprofTotalMicro (): Int64; begin result := xptimer.elapsedMicro; end; +function xprofTotalMilli (): Int64; begin result := xptimer.elapsedMilli; end; + +// all items +function xprofTotalCount (): Integer; +begin + if xptimer.isRunning then result := 0 else result := xpsused; +end; + + +// false: no sections +function xprofItReset (): Boolean; +begin + result := false; + xitcur := -1; + xitdepth := 0; + if xptimer.isRunning then exit; + if (xpsused = 0) then exit; // no sections + xitcur := 0; + assert(xpsecs[0].parent = -1); + result := true; +end; + + +// from current item to eol (not including children, but including current item) +function xprofItCount (): Integer; +var + idx: Integer; +begin + result := 0; + idx := xitcur; + while (idx <> -1) do + begin + Inc(result); + idx := xpsecs[idx].next; + end; +end; + + +// current item info +function xprofItName (): AnsiString; begin if (xitcur = -1) then result := '' else result := xpsecs[xitcur].name; end; +function xprofItMicro (): Int64; begin if (xitcur = -1) then result := 0 else result := xpsecs[xitcur].timer.elapsedMicro; end; +function xprofItMilli (): Int64; begin if (xitcur = -1) then result := 0 else result := xpsecs[xitcur].timer.elapsedMilli; end; +function xprofItHasChildren (): Boolean; begin if (xitcur = -1) then result := false else result := (xpsecs[xitcur].firstChild <> -1); end; +function xprofItIsChild (): Boolean; begin if (xitcur = -1) then result := false else result := (xpsecs[xitcur].parent <> -1); end; +function xprofItDepth (): Integer; begin result := xitdepth; end; + +// dive into childrens +function xprofItDive (): Boolean; +begin + if (xitcur = -1) or (xpsecs[xitcur].firstChild = -1) then + begin + result := false; + end + else + begin + result := true; + xitcur := xpsecs[xitcur].firstChild; + Inc(xitdepth); + end; +end; + +// pop into parent +function xprofItPop (): Boolean; +begin + if (xitcur = -1) or (xpsecs[xitcur].parent = -1) then + begin + result := false; + end + else + begin + result := true; + xitcur := xpsecs[xitcur].parent; + Dec(xitdepth); + end; +end; + +// move to next sibling; false: no more siblings (and current item is unchanged) +function xprofItNext (): Boolean; +begin + if (xitcur = -1) or (xpsecs[xitcur].next = -1) then + begin + result := false; + end + else + begin + result := true; + xitcur := xpsecs[xitcur].next; + end; +end; + +{$ELSE} +procedure xprofBegin (reallyActivate: Boolean=true); begin end; +procedure xprofEnd (); begin end; +procedure xprofBeginSection (name: AnsiString); begin end; +procedure xprofEndSection (); begin end; + +function xprofTotalMicro (): Int64; begin result := 0; end; +function xprofTotalMilli (): Int64; begin result := 0; end; +function xprofTotalCount (): Integer; begin result := 0; end; + +function xprofItReset (): Boolean; begin result := false; end; +function xprofItCount (): Integer; begin result := 0; end; +// current item info +function xprofItName (): AnsiString; begin result := ''; end; +function xprofItMicro (): Int64; begin result := 0; end; +function xprofItMilli (): Int64; begin result := 0; end; +function xprofItHasChildren (): Boolean; begin result := false; end; +function xprofItIsChild (): Boolean; begin result := false; end; + +function xprofItDepth (): Integer; begin result := 0; end; + +function xprofItDive (): Boolean; begin result := false; end; +function xprofItPop (): Boolean; begin result := false; end; +function xprofItNext (): Boolean; begin result := false; end; +{$ENDIF} + +begin + {$IF DEFINED(STOPWATCH_IS_HERE)} + xprofGlobalInit(); + {$ENDIF} +end.