From 491506fafda515e09189df68bac7db1b667658d0 Mon Sep 17 00:00:00 2001 From: Joe Date: Sun, 1 Mar 2026 14:20:09 -0600 Subject: [PATCH] Refactor log message formatting for timing information consistency - Updated log messages across `ApiContext`, `ServeSession`, `Reconciler`, and `App` to use consistent formatting for timing information, replacing placeholder syntax with `string.format` for improved clarity. - Enhanced trace logs to provide more precise execution time measurements during various operations, including connection, reading, writing, and patch application processes. These changes aim to standardize logging practices and improve the readability of timing information in the application. --- plugin/src/ApiContext.lua | 30 ++++++------- plugin/src/App/init.lua | 5 ++- plugin/src/Reconciler/applyPatch.lua | 25 ++++++++--- plugin/src/Reconciler/diff.lua | 4 +- plugin/src/Reconciler/hydrate.lua | 8 ++-- plugin/src/ServeSession.lua | 66 ++++++++++++++++++++-------- 6 files changed, 92 insertions(+), 46 deletions(-) diff --git a/plugin/src/ApiContext.lua b/plugin/src/ApiContext.lua index b2e7027c..01c98cd1 100644 --- a/plugin/src/ApiContext.lua +++ b/plugin/src/ApiContext.lua @@ -169,8 +169,8 @@ function ApiContext:connect() return Http.get(url) :andThen(function(response) Log.trace( - "[TIMING] ApiContext:connect() HTTP response received ({:.1} ms)", - (os.clock() - connectClock) * 1000 + "[TIMING] ApiContext:connect() HTTP response received ({} ms)", + string.format("%.1f", (os.clock() - connectClock) * 1000) ) return response end) @@ -191,8 +191,8 @@ function ApiContext:connect() :andThen(function(body) self.__sessionId = body.sessionId Log.trace( - "[TIMING] ApiContext:connect() fully validated ({:.1} ms), sessionId={}", - (os.clock() - connectClock) * 1000, + "[TIMING] ApiContext:connect() fully validated ({} ms), sessionId={}", + string.format("%.1f", (os.clock() - connectClock) * 1000), body.sessionId ) @@ -208,8 +208,8 @@ function ApiContext:read(ids) return Http.get(url) :andThen(function(response) Log.trace( - "[TIMING] ApiContext:read() HTTP response received ({:.1} ms, {} bytes)", - (os.clock() - readClock) * 1000, + "[TIMING] ApiContext:read() HTTP response received ({} ms, {} bytes)", + string.format("%.1f", (os.clock() - readClock) * 1000), if response.body then #response.body else 0 ) return response @@ -218,21 +218,19 @@ function ApiContext:read(ids) :andThen(function(response) local decodeClock = os.clock() Log.trace("[TIMING] ApiContext:read() msgpack decode starting") - return Http.Response.msgpack(response):andThen(function(body) - Log.trace( - "[TIMING] ApiContext:read() msgpack decode completed ({:.1} ms)", - (os.clock() - decodeClock) * 1000 - ) - return body - end) + return Http.Response.msgpack(response) end) :andThen(function(body) + Log.trace("[TIMING] ApiContext:read() msgpack decoded") if body.sessionId ~= self.__sessionId then return Promise.reject("Server changed ID") end assert(validateApiRead(body)) - Log.trace("[TIMING] ApiContext:read() fully completed ({:.1} ms)", (os.clock() - readClock) * 1000) + Log.trace( + "[TIMING] ApiContext:read() fully completed ({} ms)", + string.format("%.1f", (os.clock() - readClock) * 1000) + ) return body end) @@ -332,8 +330,8 @@ function ApiContext:connectWebSocket(packetHandlers) Url = url, }) Log.trace( - "[TIMING] WebSocket CreateWebStreamClient ({:.1} ms, success={})", - (os.clock() - wsClock) * 1000, + "[TIMING] WebSocket CreateWebStreamClient ({} ms, success={})", + string.format("%.1f", (os.clock() - wsClock) * 1000), success ) if not success then diff --git a/plugin/src/App/init.lua b/plugin/src/App/init.lua index 62ab301f..e5bef9e5 100644 --- a/plugin/src/App/init.lua +++ b/plugin/src/App/init.lua @@ -1006,7 +1006,10 @@ function App:startSession() Log.trace("[TIMING] PatchTree.build() starting") local patchTree = PatchTree.build(patch, instanceMap, { "Property", "Current", "Incoming" }, serverInfo.gitMetadata) - Log.trace("[TIMING] PatchTree.build() completed ({:.1} ms)", (os.clock() - patchTreeClock) * 1000) + Log.trace( + "[TIMING] PatchTree.build() completed ({} ms)", + string.format("%.1f", (os.clock() - patchTreeClock) * 1000) + ) self:setState({ appStatus = AppStatus.Confirming, patchTree = patchTree, diff --git a/plugin/src/Reconciler/applyPatch.lua b/plugin/src/Reconciler/applyPatch.lua index afb79e3b..326cdb34 100644 --- a/plugin/src/Reconciler/applyPatch.lua +++ b/plugin/src/Reconciler/applyPatch.lua @@ -77,7 +77,10 @@ local function applyPatch(instanceMap, patch) end end - Log.trace("[TIMING] applyPatch() removals completed ({:.1} ms)", (os.clock() - removalClock) * 1000) + Log.trace( + "[TIMING] applyPatch() removals completed ({} ms)", + string.format("%.1f", (os.clock() - removalClock) * 1000) + ) -- Detect echoed additions from DescendantAdded handler. -- When the plugin pre-inserts instances with temp IDs and the server @@ -160,7 +163,10 @@ local function applyPatch(instanceMap, patch) end end - Log.trace("[TIMING] applyPatch() additions completed ({:.1} ms)", (os.clock() - additionClock) * 1000) + Log.trace( + "[TIMING] applyPatch() additions completed ({} ms)", + string.format("%.1f", (os.clock() - additionClock) * 1000) + ) local updateClock = os.clock() Log.trace("[TIMING] applyPatch() updates starting ({} updates)", #patch.updated) @@ -332,14 +338,23 @@ local function applyPatch(instanceMap, patch) end end - Log.trace("[TIMING] applyPatch() updates completed ({:.1} ms)", (os.clock() - updateClock) * 1000) + Log.trace( + "[TIMING] applyPatch() updates completed ({} ms)", + string.format("%.1f", (os.clock() - updateClock) * 1000) + ) local refsClock = os.clock() Log.trace("[TIMING] applyPatch() deferred refs starting ({} refs)", #deferredRefs) applyDeferredRefs(instanceMap, deferredRefs, unappliedPatch) - Log.trace("[TIMING] applyPatch() deferred refs completed ({:.1} ms)", (os.clock() - refsClock) * 1000) + Log.trace( + "[TIMING] applyPatch() deferred refs completed ({} ms)", + string.format("%.1f", (os.clock() - refsClock) * 1000) + ) - Log.trace("[TIMING] applyPatch() total completed ({:.1} ms)", (os.clock() - applyPatchClock) * 1000) + Log.trace( + "[TIMING] applyPatch() total completed ({} ms)", + string.format("%.1f", (os.clock() - applyPatchClock) * 1000) + ) return unappliedPatch end diff --git a/plugin/src/Reconciler/diff.lua b/plugin/src/Reconciler/diff.lua index 52d6f811..b0c506f3 100644 --- a/plugin/src/Reconciler/diff.lua +++ b/plugin/src/Reconciler/diff.lua @@ -259,12 +259,12 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo) addedCount += 1 end Log.trace( - "[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({:.1} ms)", + "[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({} ms)", diffCount, #patch.removed, addedCount, #patch.updated, - (os.clock() - diffClock) * 1000 + string.format("%.1f", (os.clock() - diffClock) * 1000) ) return true, patch diff --git a/plugin/src/Reconciler/hydrate.lua b/plugin/src/Reconciler/hydrate.lua index 5f1e50e4..6230bea9 100644 --- a/plugin/src/Reconciler/hydrate.lua +++ b/plugin/src/Reconciler/hydrate.lua @@ -68,9 +68,9 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess if matchElapsed > 10 then Log.trace( - "[TIMING] matchChildren for '{}' took {:.1} ms ({} virtual, {} studio, {} matched)", + "[TIMING] matchChildren for '{}' took {} ms ({} virtual, {} studio, {} matched)", virtualInstance.Name, - matchElapsed, + string.format("%.1f", matchElapsed), #validVirtualIds, #existingChildren, #result.matched @@ -98,10 +98,10 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess if isRoot then Log.trace( - "[TIMING] hydrate() completed: {} instances processed, {} matched ({:.1} ms total)", + "[TIMING] hydrate() completed: {} instances processed, {} matched ({} ms total)", session.hydrateCount, #result.matched, - (os.clock() - session.hydrateClock) * 1000 + string.format("%.1f", (os.clock() - session.hydrateClock) * 1000) ) end end diff --git a/plugin/src/ServeSession.lua b/plugin/src/ServeSession.lua index 661c0f28..0ea37bef 100644 --- a/plugin/src/ServeSession.lua +++ b/plugin/src/ServeSession.lua @@ -335,7 +335,10 @@ function ServeSession:start() self.__apiContext :connect() :andThen(function(serverInfo) - Log.trace("[TIMING] ApiContext:connect() completed ({:.1} ms)", (os.clock() - sessionStartClock) * 1000) + Log.trace( + "[TIMING] ApiContext:connect() completed ({} ms)", + string.format("%.1f", (os.clock() - sessionStartClock) * 1000) + ) self:setLoadingText("Loading initial data from server...") -- Configure sync mode based on server capabilities @@ -351,8 +354,8 @@ function ServeSession:start() Log.trace("[TIMING] __computeInitialPatch() starting") return self:__computeInitialPatch(serverInfo):andThen(function(catchUpPatch) Log.trace( - "[TIMING] __computeInitialPatch() completed ({:.1} ms)", - (os.clock() - computePatchClock) * 1000 + "[TIMING] __computeInitialPatch() completed ({} ms)", + string.format("%.1f", (os.clock() - computePatchClock) * 1000) ) self:setLoadingText("Starting sync loop...") @@ -373,22 +376,28 @@ function ServeSession:start() self:__stopInternal(err) end end) - Log.trace("[TIMING] connectWebSocket() initiated ({:.1} ms)", (os.clock() - wsClock) * 1000) + Log.trace( + "[TIMING] connectWebSocket() initiated ({} ms)", + string.format("%.1f", (os.clock() - wsClock) * 1000) + ) local confirmClock = os.clock() Log.trace("[TIMING] __confirmAndApplyInitialPatch() starting") -- Now show confirmation and wait for user decision return self:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo):andThen(function(...) Log.trace( - "[TIMING] __confirmAndApplyInitialPatch() completed ({:.1} ms)", - (os.clock() - confirmClock) * 1000 + "[TIMING] __confirmAndApplyInitialPatch() completed ({} ms)", + string.format("%.1f", (os.clock() - confirmClock) * 1000) ) return ... end) end) end) :andThen(function() - Log.trace("[TIMING] ServeSession:start() total elapsed ({:.1} ms)", (os.clock() - sessionStartClock) * 1000) + Log.trace( + "[TIMING] ServeSession:start() total elapsed ({} ms)", + string.format("%.1f", (os.clock() - sessionStartClock) * 1000) + ) -- Initial sync is fully complete (including any writes to the server) if self.__initialSyncCompleteCallback ~= nil then self.__initialSyncCompleteCallback() @@ -595,8 +604,8 @@ function ServeSession:__applyPatch(patch) Log.trace("[TIMING] reconciler:applyPatch() starting") local patchApplySuccess, unappliedPatch = pcall(self.__reconciler.applyPatch, self.__reconciler, patch) Log.trace( - "[TIMING] reconciler:applyPatch() completed ({:.1} ms, success={})", - (os.clock() - reconcilerClock) * 1000, + "[TIMING] reconciler:applyPatch() completed ({} ms, success={})", + string.format("%.1f", (os.clock() - reconcilerClock) * 1000), patchApplySuccess ) if not patchApplySuccess then @@ -639,7 +648,10 @@ function ServeSession:__applyPatch(patch) end end) self.__applyingPatch = false - Log.trace("[TIMING] Sync fallback phase completed ({:.1} ms)", (os.clock() - fallbackClock) * 1000) + Log.trace( + "[TIMING] Sync fallback phase completed ({} ms)", + string.format("%.1f", (os.clock() - fallbackClock) * 1000) + ) if not fallbackOk then Log.warn("Sync fallback errored: {}", fallbackErr) @@ -674,7 +686,10 @@ function ServeSession:__computeInitialPatch(serverInfo) local readClock = os.clock() Log.trace("[TIMING] ApiContext:read() starting") return self.__apiContext:read({ serverInfo.rootInstanceId }):andThen(function(readResponseBody) - Log.trace("[TIMING] ApiContext:read() completed ({:.1} ms)", (os.clock() - readClock) * 1000) + Log.trace( + "[TIMING] ApiContext:read() completed ({} ms)", + string.format("%.1f", (os.clock() - readClock) * 1000) + ) local instanceCount = 0 for _ in pairs(readResponseBody.instances) do @@ -694,7 +709,10 @@ function ServeSession:__computeInitialPatch(serverInfo) Log.trace("[TIMING] reconciler:hydrate() starting ({} virtual instances)", instanceCount) local matchingSession = Matching.newSession() self.__reconciler:hydrate(readResponseBody.instances, serverInfo.rootInstanceId, game, matchingSession) - Log.trace("[TIMING] reconciler:hydrate() completed ({:.1} ms)", (os.clock() - hydrateClock) * 1000) + Log.trace( + "[TIMING] reconciler:hydrate() completed ({} ms)", + string.format("%.1f", (os.clock() - hydrateClock) * 1000) + ) local hydratedCount = 0 for _ in pairs(self.__instanceMap.fromIds) do @@ -710,7 +728,10 @@ function ServeSession:__computeInitialPatch(serverInfo) Log.trace("[TIMING] reconciler:diff() starting") local success, catchUpPatch = self.__reconciler:diff(readResponseBody.instances, serverInfo.rootInstanceId, serverInfo) - Log.trace("[TIMING] reconciler:diff() completed ({:.1} ms)", (os.clock() - diffClock) * 1000) + Log.trace( + "[TIMING] reconciler:diff() completed ({} ms)", + string.format("%.1f", (os.clock() - diffClock) * 1000) + ) if not success then Log.error("Could not compute a diff to catch up to the Rojo server: {:#?}", catchUpPatch) @@ -760,9 +781,9 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) Log.trace("[TIMING] Waiting for user confirmation...") userDecision = self.__userConfirmCallback(self.__instanceMap, catchUpPatch, serverInfo) Log.trace( - "[TIMING] User confirmation received: {} ({:.1} ms wait)", + "[TIMING] User confirmation received: {} ({} ms wait)", tostring(userDecision), - (os.clock() - confirmWaitClock) * 1000 + string.format("%.1f", (os.clock() - confirmWaitClock) * 1000) ) -- Clear confirmation state flags @@ -789,7 +810,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) local applyPatchClock = os.clock() Log.trace("[TIMING] __applyPatch() starting (Accept path)") self:__applyPatch(catchUpPatch) - Log.trace("[TIMING] __applyPatch() completed ({:.1} ms)", (os.clock() - applyPatchClock) * 1000) + Log.trace( + "[TIMING] __applyPatch() completed ({} ms)", + string.format("%.1f", (os.clock() - applyPatchClock) * 1000) + ) return Promise.resolve() elseif type(userDecision) == "table" and userDecision.type == "Confirm" then -- New: Apply based on per-item selections @@ -960,7 +984,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) local pushClock = os.clock() Log.trace("[TIMING] __applyPatch() starting (Confirm push path)") self:__applyPatch(pushPatch) - Log.trace("[TIMING] __applyPatch() completed ({:.1} ms)", (os.clock() - pushClock) * 1000) + Log.trace( + "[TIMING] __applyPatch() completed ({} ms)", + string.format("%.1f", (os.clock() - pushClock) * 1000) + ) end if Settings:get("oneShotSync") then @@ -990,7 +1017,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) local writeClock = os.clock() Log.trace("[TIMING] ApiContext:write() starting (pull patch)") return self.__apiContext:write(pullPatch, stageIds):andThen(function(...) - Log.trace("[TIMING] ApiContext:write() completed ({:.1} ms)", (os.clock() - writeClock) * 1000) + Log.trace( + "[TIMING] ApiContext:write() completed ({} ms)", + string.format("%.1f", (os.clock() - writeClock) * 1000) + ) return ... end) end