hakowork/rojo
3
0
Fork 0
mirror of https://github.com/rojo-rbx/rojo.git synced 2026-10-24 06:34:09 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions

Refactor log message formatting for timing information consistency

Browse source 
- 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.
This commit is contained in:
Joe 2026-03-01 14:20:09 -06:00
parent 7b9d44953b
commit 491506fafd
6 changed files with 92 additions and 46 deletions
Download patch file Download diff file Expand all files Collapse all files

30
plugin/src/ApiContext.lua
View file

@ -169,8 +169,8 @@ function ApiContext:connect()
return Http.get(url) return Http.get(url)
:andThen(function(response) :andThen(function(response)
Log.trace( Log.trace(
"[TIMING] ApiContext:connect() HTTP response received ({:.1} ms)", "[TIMING] ApiContext:connect() HTTP response received ({} ms)",
(os.clock() - connectClock) * 1000 string.format("%.1f", (os.clock() - connectClock) * 1000)
) )
return response return response
end) end)
@ -191,8 +191,8 @@ function ApiContext:connect()
:andThen(function(body) :andThen(function(body)
self.__sessionId = body.sessionId self.__sessionId = body.sessionId
Log.trace( Log.trace(
"[TIMING] ApiContext:connect() fully validated ({:.1} ms), sessionId={}", "[TIMING] ApiContext:connect() fully validated ({} ms), sessionId={}",
(os.clock() - connectClock) * 1000, string.format("%.1f", (os.clock() - connectClock) * 1000),
body.sessionId body.sessionId
) )
@ -208,8 +208,8 @@ function ApiContext:read(ids)
return Http.get(url) return Http.get(url)
:andThen(function(response) :andThen(function(response)
Log.trace( Log.trace(
"[TIMING] ApiContext:read() HTTP response received ({:.1} ms, {} bytes)", "[TIMING] ApiContext:read() HTTP response received ({} ms, {} bytes)",
(os.clock() - readClock) * 1000, string.format("%.1f", (os.clock() - readClock) * 1000),
if response.body then #response.body else 0 if response.body then #response.body else 0
) )
return response return response
@ -218,21 +218,19 @@ function ApiContext:read(ids)
:andThen(function(response) :andThen(function(response)
local decodeClock = os.clock() local decodeClock = os.clock()
Log.trace("[TIMING] ApiContext:read() msgpack decode starting") Log.trace("[TIMING] ApiContext:read() msgpack decode starting")
return Http.Response.msgpack(response):andThen(function(body) return Http.Response.msgpack(response)
Log.trace(
"[TIMING] ApiContext:read() msgpack decode completed ({:.1} ms)",
(os.clock() - decodeClock) * 1000
)
return body
end)
end) end)
:andThen(function(body) :andThen(function(body)
Log.trace("[TIMING] ApiContext:read() msgpack decoded")
if body.sessionId ~= self.__sessionId then if body.sessionId ~= self.__sessionId then
return Promise.reject("Server changed ID") return Promise.reject("Server changed ID")
end end
assert(validateApiRead(body)) 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 return body
end) end)
@ -332,8 +330,8 @@ function ApiContext:connectWebSocket(packetHandlers)
Url = url, Url = url,
}) })
Log.trace( Log.trace(
"[TIMING] WebSocket CreateWebStreamClient ({:.1} ms, success={})", "[TIMING] WebSocket CreateWebStreamClient ({} ms, success={})",
(os.clock() - wsClock) * 1000, string.format("%.1f", (os.clock() - wsClock) * 1000),
success success
) )
if not success then if not success then

5
plugin/src/App/init.lua
View file

@ -1006,7 +1006,10 @@ function App:startSession()
Log.trace("[TIMING] PatchTree.build() starting") Log.trace("[TIMING] PatchTree.build() starting")
local patchTree = local patchTree =
PatchTree.build(patch, instanceMap, { "Property", "Current", "Incoming" }, serverInfo.gitMetadata) 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({ self:setState({
appStatus = AppStatus.Confirming, appStatus = AppStatus.Confirming,
patchTree = patchTree, patchTree = patchTree,

25
plugin/src/Reconciler/applyPatch.lua
View file

@ -77,7 +77,10 @@ local function applyPatch(instanceMap, patch)
end end
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. -- Detect echoed additions from DescendantAdded handler.
-- When the plugin pre-inserts instances with temp IDs and the server -- When the plugin pre-inserts instances with temp IDs and the server
@ -160,7 +163,10 @@ local function applyPatch(instanceMap, patch)
end end
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() local updateClock = os.clock()
Log.trace("[TIMING] applyPatch() updates starting ({} updates)", #patch.updated) Log.trace("[TIMING] applyPatch() updates starting ({} updates)", #patch.updated)
@ -332,14 +338,23 @@ local function applyPatch(instanceMap, patch)
end end
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() local refsClock = os.clock()
Log.trace("[TIMING] applyPatch() deferred refs starting ({} refs)", #deferredRefs) Log.trace("[TIMING] applyPatch() deferred refs starting ({} refs)", #deferredRefs)
applyDeferredRefs(instanceMap, deferredRefs, unappliedPatch) 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 return unappliedPatch
end end

4
plugin/src/Reconciler/diff.lua
View file

@ -259,12 +259,12 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo)
addedCount += 1 addedCount += 1
end end
Log.trace( Log.trace(
"[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({:.1} ms)", "[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({} ms)",
diffCount, diffCount,
#patch.removed, #patch.removed,
addedCount, addedCount,
#patch.updated, #patch.updated,
(os.clock() - diffClock) * 1000 string.format("%.1f", (os.clock() - diffClock) * 1000)
) )
return true, patch return true, patch

8
plugin/src/Reconciler/hydrate.lua
View file

@ -68,9 +68,9 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess
if matchElapsed > 10 then if matchElapsed > 10 then
Log.trace( Log.trace(
"[TIMING] matchChildren for '{}' took {:.1} ms ({} virtual, {} studio, {} matched)", "[TIMING] matchChildren for '{}' took {} ms ({} virtual, {} studio, {} matched)",
virtualInstance.Name, virtualInstance.Name,
matchElapsed, string.format("%.1f", matchElapsed),
#validVirtualIds, #validVirtualIds,
#existingChildren, #existingChildren,
#result.matched #result.matched
@ -98,10 +98,10 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess
if isRoot then if isRoot then
Log.trace( Log.trace(
"[TIMING] hydrate() completed: {} instances processed, {} matched ({:.1} ms total)", "[TIMING] hydrate() completed: {} instances processed, {} matched ({} ms total)",
session.hydrateCount, session.hydrateCount,
#result.matched, #result.matched,
(os.clock() - session.hydrateClock) * 1000 string.format("%.1f", (os.clock() - session.hydrateClock) * 1000)
) )
end end
end end

66
plugin/src/ServeSession.lua
View file

@ -335,7 +335,10 @@ function ServeSession:start()
self.__apiContext self.__apiContext
:connect() :connect()
:andThen(function(serverInfo) :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...") self:setLoadingText("Loading initial data from server...")
-- Configure sync mode based on server capabilities -- Configure sync mode based on server capabilities
@ -351,8 +354,8 @@ function ServeSession:start()
Log.trace("[TIMING] __computeInitialPatch() starting") Log.trace("[TIMING] __computeInitialPatch() starting")
return self:__computeInitialPatch(serverInfo):andThen(function(catchUpPatch) return self:__computeInitialPatch(serverInfo):andThen(function(catchUpPatch)
Log.trace( Log.trace(
"[TIMING] __computeInitialPatch() completed ({:.1} ms)", "[TIMING] __computeInitialPatch() completed ({} ms)",
(os.clock() - computePatchClock) * 1000 string.format("%.1f", (os.clock() - computePatchClock) * 1000)
) )
self:setLoadingText("Starting sync loop...") self:setLoadingText("Starting sync loop...")
@ -373,22 +376,28 @@ function ServeSession:start()
self:__stopInternal(err) self:__stopInternal(err)
end end
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() local confirmClock = os.clock()
Log.trace("[TIMING] __confirmAndApplyInitialPatch() starting") Log.trace("[TIMING] __confirmAndApplyInitialPatch() starting")
-- Now show confirmation and wait for user decision -- Now show confirmation and wait for user decision
return self:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo):andThen(function(...) return self:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo):andThen(function(...)
Log.trace( Log.trace(
"[TIMING] __confirmAndApplyInitialPatch() completed ({:.1} ms)", "[TIMING] __confirmAndApplyInitialPatch() completed ({} ms)",
(os.clock() - confirmClock) * 1000 string.format("%.1f", (os.clock() - confirmClock) * 1000)
) )
return ... return ...
end) end)
end) end)
end) end)
:andThen(function() :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) -- Initial sync is fully complete (including any writes to the server)
if self.__initialSyncCompleteCallback ~= nil then if self.__initialSyncCompleteCallback ~= nil then
self.__initialSyncCompleteCallback() self.__initialSyncCompleteCallback()
@ -595,8 +604,8 @@ function ServeSession:__applyPatch(patch)
Log.trace("[TIMING] reconciler:applyPatch() starting") Log.trace("[TIMING] reconciler:applyPatch() starting")
local patchApplySuccess, unappliedPatch = pcall(self.__reconciler.applyPatch, self.__reconciler, patch) local patchApplySuccess, unappliedPatch = pcall(self.__reconciler.applyPatch, self.__reconciler, patch)
Log.trace( Log.trace(
"[TIMING] reconciler:applyPatch() completed ({:.1} ms, success={})", "[TIMING] reconciler:applyPatch() completed ({} ms, success={})",
(os.clock() - reconcilerClock) * 1000, string.format("%.1f", (os.clock() - reconcilerClock) * 1000),
patchApplySuccess patchApplySuccess
) )
if not patchApplySuccess then if not patchApplySuccess then
@ -639,7 +648,10 @@ function ServeSession:__applyPatch(patch)
end end
end) end)
self.__applyingPatch = false 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 if not fallbackOk then
Log.warn("Sync fallback errored: {}", fallbackErr) Log.warn("Sync fallback errored: {}", fallbackErr)
@ -674,7 +686,10 @@ function ServeSession:__computeInitialPatch(serverInfo)
local readClock = os.clock() local readClock = os.clock()
Log.trace("[TIMING] ApiContext:read() starting") Log.trace("[TIMING] ApiContext:read() starting")
return self.__apiContext:read({ serverInfo.rootInstanceId }):andThen(function(readResponseBody) 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 local instanceCount = 0
for _ in pairs(readResponseBody.instances) do for _ in pairs(readResponseBody.instances) do
@ -694,7 +709,10 @@ function ServeSession:__computeInitialPatch(serverInfo)
Log.trace("[TIMING] reconciler:hydrate() starting ({} virtual instances)", instanceCount) Log.trace("[TIMING] reconciler:hydrate() starting ({} virtual instances)", instanceCount)
local matchingSession = Matching.newSession() local matchingSession = Matching.newSession()
self.__reconciler:hydrate(readResponseBody.instances, serverInfo.rootInstanceId, game, matchingSession) 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 local hydratedCount = 0
for _ in pairs(self.__instanceMap.fromIds) do for _ in pairs(self.__instanceMap.fromIds) do
@ -710,7 +728,10 @@ function ServeSession:__computeInitialPatch(serverInfo)
Log.trace("[TIMING] reconciler:diff() starting") Log.trace("[TIMING] reconciler:diff() starting")
local success, catchUpPatch = local success, catchUpPatch =
self.__reconciler:diff(readResponseBody.instances, serverInfo.rootInstanceId, serverInfo) 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 if not success then
Log.error("Could not compute a diff to catch up to the Rojo server: {:#?}", catchUpPatch) 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...") Log.trace("[TIMING] Waiting for user confirmation...")
userDecision = self.__userConfirmCallback(self.__instanceMap, catchUpPatch, serverInfo) userDecision = self.__userConfirmCallback(self.__instanceMap, catchUpPatch, serverInfo)
Log.trace( Log.trace(
"[TIMING] User confirmation received: {} ({:.1} ms wait)", "[TIMING] User confirmation received: {} ({} ms wait)",
tostring(userDecision), tostring(userDecision),
(os.clock() - confirmWaitClock) * 1000 string.format("%.1f", (os.clock() - confirmWaitClock) * 1000)
) )
-- Clear confirmation state flags -- Clear confirmation state flags
@ -789,7 +810,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
local applyPatchClock = os.clock() local applyPatchClock = os.clock()
Log.trace("[TIMING] __applyPatch() starting (Accept path)") Log.trace("[TIMING] __applyPatch() starting (Accept path)")
self:__applyPatch(catchUpPatch) 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() return Promise.resolve()
elseif type(userDecision) == "table" and userDecision.type == "Confirm" then elseif type(userDecision) == "table" and userDecision.type == "Confirm" then
-- New: Apply based on per-item selections -- New: Apply based on per-item selections
@ -960,7 +984,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
local pushClock = os.clock() local pushClock = os.clock()
Log.trace("[TIMING] __applyPatch() starting (Confirm push path)") Log.trace("[TIMING] __applyPatch() starting (Confirm push path)")
self:__applyPatch(pushPatch) 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 end
if Settings:get("oneShotSync") then if Settings:get("oneShotSync") then
@ -990,7 +1017,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
local writeClock = os.clock() local writeClock = os.clock()
Log.trace("[TIMING] ApiContext:write() starting (pull patch)") Log.trace("[TIMING] ApiContext:write() starting (pull patch)")
return self.__apiContext:write(pullPatch, stageIds):andThen(function(...) 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 ... return ...
end) end)
end end