diff --git a/cvarinfo.base b/cvarinfo.base index 12095335f..4fbbbc132 100644 --- a/cvarinfo.base +++ b/cvarinfo.base @@ -125,6 +125,7 @@ nosave bool swwm_beepboop = false; // prompts the Demolitionist to go "beep", " nosave bool swwm_oldlogo = false; // restores the old SWWM GZ logo and intro nosave string swwm_menuposehistory = ""; // stores currently seen poses for the main menu, for shuffling nosave string swwm_titlesubhistory = ""; // stores currently seen subtitles for the title screen, for shuffling +nosave noarchive int swwm_profstart = 0; // starts profiling as soon as handler is registered for specified >0 tics // minimap settings nosave bool swwm_mm_enable = true; // show a minimap below the score counter diff --git a/language.version b/language.version index 286160b12..dffa75359 100644 --- a/language.version +++ b/language.version @@ -1,3 +1,3 @@ [default] -SWWM_MODVER="\cyDEMOLITIONIST \cw1.2pre r171 \cu(Thu 24 Feb 18:50:20 CET 2022)\c-"; -SWWM_SHORTVER="\cw1.2pre r171 \cu(2022-02-24 18:50:20)\c-"; +SWWM_MODVER="\cyDEMOLITIONIST \cw1.2pre r172 \cu(Fri 25 Feb 16:51:20 CET 2022)\c-"; +SWWM_SHORTVER="\cw1.2pre r172 \cu(2022-02-25 16:51:20)\c-"; diff --git a/zscript/handler/swwm_handler_damage.zsc b/zscript/handler/swwm_handler_damage.zsc index db7661b7c..3c0c835cf 100644 --- a/zscript/handler/swwm_handler_damage.zsc +++ b/zscript/handler/swwm_handler_damage.zsc @@ -390,12 +390,12 @@ extend Class SWWMHandler override void WorldThingDamaged( WorldEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); if ( e.Damage > 0 ) DoDamageHandling(e); if ( e.DamageSource && (e.DamageSource != e.Thing) ) DoCombatHit(e); if ( (e.Thing.Health > 0) || e.Thing.bKilled || e.Thing.bCorpse ) { - if ( profiling ) worldthingdamaged_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDAMAGED); return; } DoGibThing(e); @@ -406,10 +406,10 @@ extend Class SWWMHandler e.DamageSource.DamageMobj(null,null,Actor.TELEFRAG_DAMAGE,'EndLevel'); if ( !e.Thing.player && !e.Thing.bIsMonster && !e.Thing.bCountKill && !(e.Thing is 'ScriptedMarine') ) { - if ( profiling ) worldthingdamaged_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDAMAGED); return; } DoKillScoring(e); - if ( profiling ) worldthingdamaged_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDAMAGED); } } diff --git a/zscript/handler/swwm_handler_process.zsc b/zscript/handler/swwm_handler_process.zsc index 18e7e43a9..cbb115706 100644 --- a/zscript/handler/swwm_handler_process.zsc +++ b/zscript/handler/swwm_handler_process.zsc @@ -313,15 +313,13 @@ extend Class SWWMHandler } bprofiletics = profiletics = (e.Args[0]<=0)?10:e.Args[0]; profiling = true; - worldtick_ms = 0; - worldthingspawned_ms = 0; - worldthingdestroyed_ms = 0; - worldthingdied_ms = 0; - worldthingdamaged_ms = 0; - worldthingrevived_ms = 0; - checkreplacement_ms = 0; - checkreplacee_ms = 0; - Console.Printf("Gathering data for %d tic(s)...",bprofiletics); + for ( int i=0; i<8; i++ ) + { + prof_ms[i] = 0; + prof_avg[i] = 0; + prof_calls[i] = 0; + } + Console.Printf("Gathering data for %d tic%s...",bprofiletics,(bprofiletics>1)?"s":""); return; } if ( e.IsManual ) return; diff --git a/zscript/handler/swwm_handler_replacements.zsc b/zscript/handler/swwm_handler_replacements.zsc index cc9024d68..a35e88814 100644 --- a/zscript/handler/swwm_handler_replacements.zsc +++ b/zscript/handler/swwm_handler_replacements.zsc @@ -270,18 +270,18 @@ extend Class SWWMHandler override void CheckReplacee( ReplacedEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); if ( e.Replacement is 'DSparilHax' ) e.Replacee = 'Sorcerer2'; // drla stuff, needed so boss deaths work if ( !hasdrlamonsters ) { - if ( profiling ) checkreplacee_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEE); return; } let rep = GetDRLAReplacee(e.Replacement); if ( rep ) e.Replacee = rep; - if ( profiling ) checkreplacee_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEE); } private Class GetDRLAReplacement( Class a ) @@ -549,11 +549,11 @@ extend Class SWWMHandler override void CheckReplacement( ReplaceEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); // respect final replacements if ( e.IsFinal ) { - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; } // DRLA Monsters stuff @@ -564,7 +564,7 @@ extend Class SWWMHandler { e.Replacement = rep; e.IsFinal = true; - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; } } @@ -576,7 +576,7 @@ extend Class SWWMHandler { if ( SWWMUtility.CheckDehackery(e.Replacee) ) { - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; } e.Replacement = 'SWWMHangingKeen'; @@ -585,7 +585,7 @@ extend Class SWWMHandler { if ( SWWMUtility.CheckDehackery(e.Replacee) ) { - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; } e.Replacement = 'SWWMBossBrain'; @@ -594,7 +594,7 @@ extend Class SWWMHandler { if ( !equinoxhack && (level.GetChecksum() ~== "3805A661D5C4523AFF7BF86991071043") ) { - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; // don't replace red key in Equinox MAP13 } e.Replacement = 'SWWMRedCard'; @@ -706,12 +706,12 @@ extend Class SWWMHandler else if ( e.Replacee is 'ArtiTeleport' ) e.Replacement = 'SafetyTether'; else { - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); return; } // this last part is kind of ugly, but it works // guarantees that OUR replacements are all final e.IsFinal = true; - if ( profiling ) checkreplacement_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_CHECKREPLACEMENT); } } diff --git a/zscript/handler/swwm_handler_worldthings.zsc b/zscript/handler/swwm_handler_worldthings.zsc index 2526afe01..c0701b42f 100644 --- a/zscript/handler/swwm_handler_worldthings.zsc +++ b/zscript/handler/swwm_handler_worldthings.zsc @@ -13,7 +13,7 @@ extend Class SWWMHandler override void WorldThingRevived( WorldEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); // reattach combat tracker if ( !swwm_notrack && (e.Thing.bSHOOTABLE || e.Thing.bISMONSTER) && !(e.Thing is 'LampMoth') && !(e.Thing is 'CompanionLamp') ) SWWMCombatTracker.Spawn(e.Thing); @@ -27,7 +27,7 @@ extend Class SWWMHandler } if ( !(e.Thing is 'PlayerPawn') ) { - if ( profiling ) worldthingrevived_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGREVIVED); return; } // reset some vars @@ -41,7 +41,7 @@ extend Class SWWMHandler // reset uptime since player had just died SWWMStats s = SWWMStats.Find(e.Thing.player); if ( s ) s.lastspawn = level.totaltime; - if ( profiling ) worldthingrevived_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGREVIVED); } private bool HexenMap40() @@ -76,7 +76,7 @@ extend Class SWWMHandler override void WorldThingDied( WorldEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); if ( e.Thing.default.bISMONSTER && ((e.Thing.default.bBOSS) || (e.Thing.GetSpawnHealth() >= 1000) || e.Thing.FindInventory("BossMarker")) && (alreadygold.Find(e.Thing) == alreadygold.Size()) ) { // make sure we can't farm drops from revivable enemies @@ -142,7 +142,7 @@ extend Class SWWMHandler bool gotgibbed = (!e.Thing.bDONTGIB && ((e.Inflictor && e.Inflictor.bEXTREMEDEATH) || (e.DamageSource && e.DamageSource.bEXTREMEDEATH) || (e.DamageType == 'Extreme') || (e.Thing.Health < gibhealth)) && (!e.Inflictor || !e.Inflictor.bNOEXTREMEDEATH) && (!e.DamageSource || !e.DamageSource.bNOEXTREMEDEATH)); if ( !gotgibbed ) { - if ( profiling ) worldthingdied_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDIED); return; } if ( (e.Thing.GetClass() == "Demon") || (e.Thing.GetClass() == "Spectre") ) @@ -161,7 +161,7 @@ extend Class SWWMHandler ExtraGibDeaths.GibThis(e.Thing,"ArachXDeath"); else if ( e.Thing.GetClass() == "Fatso" ) ExtraGibDeaths.GibThis(e.Thing,"FatsoXDeath"); - if ( profiling ) worldthingdied_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDIED); } private void DoKeyTagFix( Actor a ) @@ -228,13 +228,13 @@ extend Class SWWMHandler override void WorldThingDestroyed( WorldEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); // for gibber throttling if ( e.Thing is 'mkBloodDrop' ) blods_realcnt--; else if ( e.Thing is 'mkFlyingGib' ) meats_realcnt--; if ( !e.Thing.default.bSHOOTABLE && !e.Thing.default.bMISSILE && !(e.Thing is 'Inventory') && !SWWMUtility.IsBeamProj(e.Thing) ) { - if ( profiling ) worldthingdestroyed_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDESTROYED); return; } // remove from suckables @@ -245,18 +245,18 @@ extend Class SWWMHandler pos = beams.Find(e.Thing); if ( pos < beams.Size() ) beams.Delete(pos); - if ( profiling ) worldthingdestroyed_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGDESTROYED); } override void WorldThingSpawned( WorldEvent e ) { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); // for gibber throttling if ( e.Thing is 'mkBloodDrop' ) blods_realcnt++; else if ( e.Thing is 'mkFlyingGib' ) meats_realcnt++; if ( !e.Thing || SuppressMultiItem(e) ) { - if ( profiling ) worldthingspawned_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGSPAWNED); return; } IWantDieSpawn(e); @@ -441,6 +441,6 @@ extend Class SWWMHandler trk.maxhealth = trk.lasthealth = e.Thing.Health; trk.intp.Reset(trk.lasthealth); } - if ( profiling ) worldthingspawned_ms += MSTime()-curms; + if ( profiling ) ProfileTock(PT_WORLDTHINGSPAWNED); } } diff --git a/zscript/swwm_handler.zsc b/zscript/swwm_handler.zsc index 191588749..9ef70efea 100644 --- a/zscript/swwm_handler.zsc +++ b/zscript/swwm_handler.zsc @@ -30,12 +30,36 @@ Class SWWMHandler : EventHandler // profiling data bool profiling; int bprofiletics, profiletics; // how many tics to aggregate data for - uint worldtick_ms; - uint worldthingspawned_ms, worldthingdestroyed_ms, - worldthingdied_ms, worldthingdamaged_ms, - worldthingrevived_ms; - uint checkreplacement_ms, checkreplacee_ms; - uint curms; + double prof_ms[8], prof_avg[8]; + int prof_calls[8]; + double curms; + //double curns; // will require NSTime() + + enum EProfileTimer + { + PT_WORLDTICK, + PT_WORLDTHINGSPAWNED, + PT_WORLDTHINGDESTROYED, + PT_WORLDTHINGDIED, + PT_WORLDTHINGDAMAGED, + PT_WORLDTHINGREVIVED, + PT_CHECKREPLACEMENT, + PT_CHECKREPLACEE + } + + private void ProfileTick() + { + curms = MSTime(); + //curns = NSTime(); + } + private void ProfileTock( int idx ) + { + double diff = (MSTime()-curms); + //double diff = (NSTime()-curns)/1000000.; + prof_ms[idx] += diff; + prof_avg[idx] = (prof_calls[idx]>0)?(prof_avg[idx]+diff)/2.:diff; + prof_calls[idx]++; + } override void OnRegister() { @@ -71,11 +95,22 @@ Class SWWMHandler : EventHandler bludtypes.Push(list[i]); } } + // start profiling + if ( swwm_profstart <= 0 ) return; + bprofiletics = profiletics = swwm_profstart; + profiling = true; + for ( int i=0; i<8; i++ ) + { + prof_ms[i] = 0; + prof_avg[i] = 0; + prof_calls[i] = 0; + } + Console.Printf("Gathering data for %d tic%s...",bprofiletics,(bprofiletics>1)?"s":""); } override void WorldTick() { - if ( profiling ) curms = MSTime(); + if ( profiling ) ProfileTick(); LangRefresh(); QueueMaintenance(); if ( !mnotify && (level.maptime >= 5) ) @@ -112,36 +147,32 @@ Class SWWMHandler : EventHandler OneHundredPercentCheck(); SimpleTracking(); VanillaBossTick(); - if ( profiling ) + if ( !profiling ) return; + ProfileTock(PT_WorldTick); + Console.Printf("%d...",profiletics); + profiletics--; + if ( profiletics > 0 ) return; + profiling = false; + static const String prof_name[] = { - worldtick_ms += MSTime()-curms; - Console.Printf("%d...",profiletics); - profiletics--; - if ( profiletics <= 0 ) - { - profiling = false; - Console.Printf("Done!"); - Console.Printf("SWWMHandler profiling info for "..bprofiletics.." tic(s):\n" - " event | total | avg\n" - "---------------------|--------|--------\n" - " WorldTick | %-6d | %g\n" - " WorldThingSpawned | %-6d | %g\n" - " WorldThingDestroyed | %-6d | %g\n" - " WorldThingDied | %-6d | %g\n" - " WorldThingDamaged | %-6d | %g\n" - " WorldThingRevived | %-6d | %g\n" - " CheckReplacement | %-6d | %g\n" - " CheckReplacee | %-6d | %g", - worldtick_ms,double(worldtick_ms)/bprofiletics, - worldthingspawned_ms,double(worldthingspawned_ms)/bprofiletics, - worldthingdestroyed_ms,double(worldthingdestroyed_ms)/bprofiletics, - worldthingdied_ms,double(worldthingdied_ms)/bprofiletics, - worldthingdamaged_ms,double(worldthingdamaged_ms)/bprofiletics, - worldthingrevived_ms,double(worldthingrevived_ms)/bprofiletics, - checkreplacement_ms,double(checkreplacement_ms)/bprofiletics, - checkreplacee_ms,double(checkreplacee_ms)/bprofiletics); - } - } + "WorldTick ", + "WorldThingSpawned ", + "WorldThingDestroyed", + "WorldThingDied ", + "WorldThingDamaged ", + "WorldThingRevived ", + "CheckReplacement ", + "CheckReplacee " + }; + Console.Printf("Done!"); + String str = String.Format( + "SWWMHandler profiling info for %d tic%s:\n" + " event name | calls | total ms | avg ms\n" + "---------------------|-------|-----------|-----------\n", + bprofiletics,(bprofiletics>1)?"s":""); + for ( int i=0; i<8; i++ ) + str.AppendFormat(" %s | %5d | %9.6f | %9.6f\n",prof_name[i],prof_calls[i],prof_ms[i],prof_avg[i]); + Console.Printf(str); } override void PostUiTick()