use a single global debug timer #75
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
previously there were a few places that created their own timer, but this isn't needed. - in the timer util, create an exported var DebugTimer - then, in all the various low-level functions, call .Mark on the timer.DebugTimer - finally, in the main/run method, call Stop and PrintJson before exiting, which will gather and print all of the various times
tmck-code
added
performance
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
⌚ Debug Timer Update ⏲️
There is a debug timer that can be enabled by setting the
DEBUGENV varAt various points in the code,
t.Mark("my checkpoint")is called which creates a checkpoint, and these are later broken down and summarised in the JSON outputexample
{ "Name": "ReadMetadataFromEmbedded", "StageTimes": { "00.Start": "2025-09-19T06:59:05.021184662+10:00", "01.read file": "2025-09-19T06:59:05.021195693+10:00", "02.read metadata": "2025-09-19T06:59:05.021271355+10:00" }, "StageDurations": { "00.Start": 0, "01.read file": 11031, "02.read metadata": 75662 }, "StagePercentages": { "00.Start": "0.0%", "01.read file": "12.72%", "02.read metadata": "87.28%" }, "Total": 86693, "AlignKeys": false, "Enabled": true } ╭──────────────────────────────────────────────────────────────────────────────────╮ │ w │ ╰──────╲───────────────────────────────────────────────────────────────────────────╯ ╲ ╲ ╲ ╲ ▄▄▄▄ ▄▄▄▄ ▄▄▄ ▄▄▄▄ ▄▄▄▄▄ ▄▄ ▄ ▄▄▄ ▄ ▄▀ ▄▄▄▄▄ ▄▄ ▄▄▄▄ ▄▀▄▄▀▄ ▀▄▀ ▀ ╭───────────────────────────────────────────────────╮ │ → Unown │ アンノーン (anno-n) │ small/gen7x/shiny │ ╰───────────────────────────────────────────────────╯ { "Name": "runPrintRandom", "StageTimes": { "00.Start ": "2025-09-19T06:59:05.0211782+10:00", "01.choose index ": "2025-09-19T06:59:05.021183029+10:00", "02.read metadata ": "2025-09-19T06:59:05.021369058+10:00", "03.choose entry ": "2025-09-19T06:59:05.02136999+10:00", "04.print ": "2025-09-19T06:59:05.021454839+10:00" }, "StageDurations": { "00.Start ": 0, "01.choose index ": 4829, "02.read metadata ": 186029, "03.choose entry ": 932, "04.print ": 84849 }, "StagePercentages": { "00.Start ": "0.0%", "01.choose index ": "1.75%", "02.read metadata ": "67.25%", "03.choose entry ": "0.34%", "04.print ": "30.67%" }, "Total": 276639, "AlignKeys": true, "Enabled": true } { "Name": "main", "StageTimes": { "00.Start ": "2025-09-19T06:59:05.021173441+10:00", "01.op ": "2025-09-19T06:59:05.021489234+10:00" }, "StageDurations": { "00.Start ": 0, "01.op ": 315783 }, "StagePercentages": { "00.Start ": "0.0%", "01.op ": "100.00%" }, "Total": 315783, "AlignKeys": true, "Enabled": true }Currently, there are several timers created by different modules, and they are all rendered and counted separately, which makes comparing different parts of the program a little tedious.
Introducing, a single global timer! 🌏
DebugTimer.Markon thetimer.DebugTimerOverall, this change simplifies the current implementation and usage, reduces the amount of code, and improves the functionality of this dev/debug feature
example screenshot
JSON
{ "Name": "Debug Timer", "StageTimes": { "00.Start ": "2025-09-18T19:15:41.631916+10:00", "01.parsed flags ": "2025-09-18T19:15:41.632431+10:00", "02.choose index ": "2025-09-18T19:15:41.632446+10:00", "03.read embedded file ": "2025-09-18T19:15:41.632513+10:00", "04.metadata from bytes ": "2025-09-18T19:15:41.632619+10:00", "05.choose entry ": "2025-09-18T19:15:41.63262+10:00", "06.generate names ": "2025-09-18T19:15:41.632622+10:00", "07.scan stdin ": "2025-09-18T19:15:41.632671+10:00", "08.print speech bubble ": "2025-09-18T19:15:41.632683+10:00", "09.read sprite file ": "2025-09-18T19:15:41.63279+10:00", "10.generate string ": "2025-09-18T19:15:41.632806+10:00", "11.gunzip string ": "2025-09-18T19:15:41.632878+10:00", "12.reverse string ": "2025-09-18T19:15:41.633501+10:00", "13.print to terminal ": "2025-09-18T19:15:41.634136+10:00", "14.op ": "2025-09-18T19:15:41.634139+10:00" }, "StageDurations": { "00.Start ": 0, "01.parsed flags ": 515541, "02.choose index ": 14875, "03.read embedded file ": 66459, "04.metadata from bytes ": 106375, "05.choose entry ": 1375, "06.generate names ": 1750, "07.scan stdin ": 49125, "08.print speech bubble ": 11583, "09.read sprite file ": 107583, "10.generate string ": 15125, "11.gunzip string ": 72792, "12.reverse string ": 623000, "13.print to terminal ": 634208, "14.op ": 2959 }, "StagePercentages": { "00.Start ": "0.0%", "01.parsed flags ": "23.19%", "02.choose index ": "0.67%", "03.read embedded file ": "2.99%", "04.metadata from bytes ": "4.79%", "05.choose entry ": "0.06%", "06.generate names ": "0.08%", "07.scan stdin ": "2.21%", "08.print speech bubble ": "0.52%", "09.read sprite file ": "4.84%", "10.generate string ": "0.68%", "11.gunzip string ": "3.27%", "12.reverse string ": "28.03%", "13.print to terminal ": "28.53%", "14.op ": "0.13%" }, "Total": 2222750, "AlignKeys": true, "Enabled": true }