Refactor logging level from trace to debug for performance improvement

- Updated logging statements in various functions across the ApiContext, ServeSession, and Reconciler modules to use `Log.debug` instead of `Log.trace`.
- This change aims to reduce the verbosity of logs and improve performance by limiting the amount of logged information during execution, while still retaining essential timing information for debugging purposes.
This commit is contained in:
Joe 2026-03-01 16:46:19 -06:00
parent 25ca0bb27e
commit 8b4573b578
9 changed files with 75 additions and 75 deletions

View file

@ -165,10 +165,10 @@ function ApiContext:connect()
local url = ("%s/api/rojo"):format(self.__baseUrl)
local connectClock = os.clock()
Log.trace("[TIMING] ApiContext:connect() GET {} starting", url)
Log.debug("[TIMING] ApiContext:connect() GET {} starting", url)
return Http.get(url)
:andThen(function(response)
Log.trace(
Log.debug(
"[TIMING] ApiContext:connect() HTTP response received ({} ms)",
string.format("%.1f", (os.clock() - connectClock) * 1000)
)
@ -177,7 +177,7 @@ function ApiContext:connect()
:andThen(rejectFailedRequests)
:andThen(Http.Response.msgpack)
:andThen(function(body)
Log.trace("[TIMING] ApiContext:connect() msgpack decoded")
Log.debug("[TIMING] ApiContext:connect() msgpack decoded")
return body
end)
:andThen(rejectWrongVersion)
@ -190,7 +190,7 @@ function ApiContext:connect()
:andThen(rejectWrongPlaceId)
:andThen(function(body)
self.__sessionId = body.sessionId
Log.trace(
Log.debug(
"[TIMING] ApiContext:connect() fully validated ({} ms), sessionId={}",
string.format("%.1f", (os.clock() - connectClock) * 1000),
body.sessionId
@ -204,10 +204,10 @@ function ApiContext:read(ids)
local url = ("%s/api/read/%s"):format(self.__baseUrl, table.concat(ids, ","))
local readClock = os.clock()
Log.trace("[TIMING] ApiContext:read() GET {} starting ({} ids)", url, #ids)
Log.debug("[TIMING] ApiContext:read() GET {} starting ({} ids)", url, #ids)
return Http.get(url)
:andThen(function(response)
Log.trace(
Log.debug(
"[TIMING] ApiContext:read() HTTP response received ({} ms, {} bytes)",
string.format("%.1f", (os.clock() - readClock) * 1000),
if response.body then #response.body else 0
@ -216,17 +216,17 @@ function ApiContext:read(ids)
end)
:andThen(rejectFailedRequests)
:andThen(function(response)
Log.trace("[TIMING] ApiContext:read() msgpack decode starting")
Log.debug("[TIMING] ApiContext:read() msgpack decode starting")
return Http.Response.msgpack(response)
end)
:andThen(function(body)
Log.trace("[TIMING] ApiContext:read() msgpack decoded")
Log.debug("[TIMING] ApiContext:read() msgpack decoded")
if body.sessionId ~= self.__sessionId then
return Promise.reject("Server changed ID")
end
assert(validateApiRead(body))
Log.trace(
Log.debug(
"[TIMING] ApiContext:read() fully completed ({} ms)",
string.format("%.1f", (os.clock() - readClock) * 1000)
)
@ -321,14 +321,14 @@ function ApiContext:connectWebSocket(packetHandlers)
-- Convert HTTP/HTTPS URL to WS/WSS
url = url:gsub("^http://", "ws://"):gsub("^https://", "wss://")
Log.trace("[TIMING] ApiContext:connectWebSocket() creating client for {}", url)
Log.debug("[TIMING] ApiContext:connectWebSocket() creating client for {}", url)
return Promise.new(function(resolve, reject)
local wsClock = os.clock()
local success, wsClient =
pcall(HttpService.CreateWebStreamClient, HttpService, Enum.WebStreamClientType.WebSocket, {
Url = url,
})
Log.trace(
Log.debug(
"[TIMING] WebSocket CreateWebStreamClient ({} ms, success={})",
string.format("%.1f", (os.clock() - wsClock) * 1000),
success

View file

@ -72,7 +72,7 @@ function StringDiffVisualizer:updateDiffs()
StringDiff.findDiffs((string.gsub(currentString, "\t", " ")), (string.gsub(incomingString, "\t", " ")))
local stopClock = os.clock()
Log.trace(
Log.debug(
"Diffing {} byte and {} byte strings took {} microseconds and found {} diff sections",
#currentString,
#incomingString,

View file

@ -1003,10 +1003,10 @@ function App:startSession()
connectingText = "Computing diff view...",
})
local patchTreeClock = os.clock()
Log.trace("[TIMING] PatchTree.build() starting")
Log.debug("[TIMING] PatchTree.build() starting")
local patchTree =
PatchTree.build(patch, instanceMap, { "Property", "Current", "Incoming" }, serverInfo.gitMetadata)
Log.trace(
Log.debug(
"[TIMING] PatchTree.build() completed ({} ms)",
string.format("%.1f", (os.clock() - patchTreeClock) * 1000)
)
@ -1024,7 +1024,7 @@ function App:startSession()
timeout = 7,
})
Log.trace("[TIMING] Waiting for user to confirm/reject patch...")
Log.debug("[TIMING] Waiting for user to confirm/reject patch...")
local result = self.confirmationEvent:Wait()
-- One-shot sync: Don't transition to Connected UI

View file

@ -42,7 +42,7 @@ local function applyPatch(instanceMap, patch)
)
end
Log.trace(
Log.debug(
"[TIMING] applyPatch() starting: {} removals, {} additions, {} updates",
#patch.removed,
addCount,
@ -77,7 +77,7 @@ local function applyPatch(instanceMap, patch)
end
end
Log.trace(
Log.debug(
"[TIMING] applyPatch() removals completed ({} ms)",
string.format("%.1f", (os.clock() - removalClock) * 1000)
)
@ -116,7 +116,7 @@ local function applyPatch(instanceMap, patch)
end
local additionClock = os.clock()
Log.trace("[TIMING] applyPatch() additions starting")
Log.debug("[TIMING] applyPatch() additions starting")
for id, virtualInstance in pairs(patch.added) do
if instanceMap.fromIds[id] ~= nil then
-- This instance already exists. We might've already added it in a
@ -163,13 +163,13 @@ local function applyPatch(instanceMap, patch)
end
end
Log.trace(
Log.debug(
"[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)
Log.debug("[TIMING] applyPatch() updates starting ({} updates)", #patch.updated)
for _, update in ipairs(patch.updated) do
local instance = instanceMap.fromIds[update.id]
@ -338,20 +338,20 @@ local function applyPatch(instanceMap, patch)
end
end
Log.trace(
Log.debug(
"[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)
Log.debug("[TIMING] applyPatch() deferred refs starting ({} refs)", #deferredRefs)
applyDeferredRefs(instanceMap, deferredRefs, unappliedPatch)
Log.trace(
Log.debug(
"[TIMING] applyPatch() deferred refs completed ({} ms)",
string.format("%.1f", (os.clock() - refsClock) * 1000)
)
Log.trace(
Log.debug(
"[TIMING] applyPatch() total completed ({} ms)",
string.format("%.1f", (os.clock() - applyPatchClock) * 1000)
)

View file

@ -66,7 +66,7 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo)
for _ in pairs(virtualInstances) do
virtualCount += 1
end
Log.trace("[TIMING] diff() starting ({} virtual instances to diff)", virtualCount)
Log.debug("[TIMING] diff() starting ({} virtual instances to diff)", virtualCount)
-- Build a lookup table for visible services (for ignoreHiddenServices check)
local visibleServicesSet: { [string]: boolean } = {}
@ -258,7 +258,7 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo)
for _ in pairs(patch.added) do
addedCount += 1
end
Log.trace(
Log.debug(
"[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({} ms)",
diffCount,
#patch.removed,

View file

@ -38,7 +38,7 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess
end
if isRoot then
Log.trace("[TIMING] hydrate() starting at root '{}' ({})", virtualInstance.Name, rootInstance:GetFullName())
Log.debug("[TIMING] hydrate() starting at root '{}' ({})", virtualInstance.Name, rootInstance:GetFullName())
end
instanceMap:insert(rootId, rootInstance)
@ -67,7 +67,7 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess
local matchElapsed = (os.clock() - matchClock) * 1000
if matchElapsed > 10 then
Log.trace(
Log.debug(
"[TIMING] matchChildren for '{}' took {} ms ({} virtual, {} studio, {} matched)",
virtualInstance.Name,
string.format("%.1f", matchElapsed),
@ -97,7 +97,7 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess
end
if isRoot then
Log.trace(
Log.debug(
"[TIMING] hydrate() completed: {} instances processed, {} matched ({} ms total)",
session.hydrateCount,
#result.matched,

View file

@ -330,12 +330,12 @@ function ServeSession:start()
self:setLoadingText("Connecting to server...")
local sessionStartClock = os.clock()
Log.trace("[TIMING] ServeSession:start() begun")
Log.debug("[TIMING] ServeSession:start() begun")
self.__apiContext
:connect()
:andThen(function(serverInfo)
Log.trace(
Log.debug(
"[TIMING] ApiContext:connect() completed ({} ms)",
string.format("%.1f", (os.clock() - sessionStartClock) * 1000)
)
@ -351,16 +351,16 @@ function ServeSession:start()
self.__serverInfo = serverInfo
local computePatchClock = os.clock()
Log.trace("[TIMING] __computeInitialPatch() starting")
Log.debug("[TIMING] __computeInitialPatch() starting")
return self:__computeInitialPatch(serverInfo):andThen(function(catchUpPatch)
Log.trace(
Log.debug(
"[TIMING] __computeInitialPatch() completed ({} ms)",
string.format("%.1f", (os.clock() - computePatchClock) * 1000)
)
self:setLoadingText("Starting sync loop...")
local wsClock = os.clock()
Log.trace("[TIMING] connectWebSocket() starting")
Log.debug("[TIMING] connectWebSocket() starting")
-- Connect WebSocket BEFORE showing confirmation so changes
-- during confirmation can be merged into the patch
-- Note: connectWebSocket returns a Promise that only resolves when
@ -376,16 +376,16 @@ function ServeSession:start()
self:__stopInternal(err)
end
end)
Log.trace(
Log.debug(
"[TIMING] connectWebSocket() initiated ({} ms)",
string.format("%.1f", (os.clock() - wsClock) * 1000)
)
local confirmClock = os.clock()
Log.trace("[TIMING] __confirmAndApplyInitialPatch() starting")
Log.debug("[TIMING] __confirmAndApplyInitialPatch() starting")
-- Now show confirmation and wait for user decision
return self:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo):andThen(function(...)
Log.trace(
Log.debug(
"[TIMING] __confirmAndApplyInitialPatch() completed ({} ms)",
string.format("%.1f", (os.clock() - confirmClock) * 1000)
)
@ -394,7 +394,7 @@ function ServeSession:start()
end)
end)
:andThen(function()
Log.trace(
Log.debug(
"[TIMING] ServeSession:start() total elapsed ({} ms)",
string.format("%.1f", (os.clock() - sessionStartClock) * 1000)
)
@ -601,9 +601,9 @@ function ServeSession:__applyPatch(patch)
self.__applyingPatch = true
local reconcilerClock = os.clock()
Log.trace("[TIMING] reconciler:applyPatch() starting")
Log.debug("[TIMING] reconciler:applyPatch() starting")
local patchApplySuccess, unappliedPatch = pcall(self.__reconciler.applyPatch, self.__reconciler, patch)
Log.trace(
Log.debug(
"[TIMING] reconciler:applyPatch() completed ({} ms, success={})",
string.format("%.1f", (os.clock() - reconcilerClock) * 1000),
patchApplySuccess
@ -621,7 +621,7 @@ function ServeSession:__applyPatch(patch)
local fallbackClock = os.clock()
local fallbackOk, fallbackErr = pcall(function()
if Settings:get("enableSyncFallback") and not PatchSet.isEmpty(unappliedPatch) then
Log.trace("[TIMING] Sync fallback starting (unapplied patch is non-empty)")
Log.debug("[TIMING] Sync fallback starting (unapplied patch is non-empty)")
-- Some changes did not apply, let's try replacing them instead
local addedIdList = PatchSet.addedIdList(unappliedPatch)
local updatedIdList = PatchSet.updatedIdList(unappliedPatch)
@ -648,7 +648,7 @@ function ServeSession:__applyPatch(patch)
end
end)
self.__applyingPatch = false
Log.trace(
Log.debug(
"[TIMING] Sync fallback phase completed ({} ms)",
string.format("%.1f", (os.clock() - fallbackClock) * 1000)
)
@ -684,9 +684,9 @@ end
function ServeSession:__computeInitialPatch(serverInfo)
local readClock = os.clock()
Log.trace("[TIMING] ApiContext:read() starting")
Log.debug("[TIMING] ApiContext:read() starting")
return self.__apiContext:read({ serverInfo.rootInstanceId }):andThen(function(readResponseBody)
Log.trace(
Log.debug(
"[TIMING] ApiContext:read() completed ({} ms)",
string.format("%.1f", (os.clock() - readClock) * 1000)
)
@ -695,7 +695,7 @@ function ServeSession:__computeInitialPatch(serverInfo)
for _ in pairs(readResponseBody.instances) do
instanceCount += 1
end
Log.trace("[TIMING] Read response contains {} instances", instanceCount)
Log.debug("[TIMING] Read response contains {} instances", instanceCount)
-- Tell the API Context that we're up-to-date with the version of
-- the tree defined in this response.
@ -706,10 +706,10 @@ function ServeSession:__computeInitialPatch(serverInfo)
Log.trace("Matching existing Roblox instances to Rojo IDs")
self:setLoadingText("Hydrating instance map...")
local hydrateClock = os.clock()
Log.trace("[TIMING] reconciler:hydrate() starting ({} virtual instances)", instanceCount)
Log.debug("[TIMING] reconciler:hydrate() starting ({} virtual instances)", instanceCount)
local matchingSession = Matching.newSession()
self.__reconciler:hydrate(readResponseBody.instances, serverInfo.rootInstanceId, game, matchingSession)
Log.trace(
Log.debug(
"[TIMING] reconciler:hydrate() completed ({} ms)",
string.format("%.1f", (os.clock() - hydrateClock) * 1000)
)
@ -718,17 +718,17 @@ function ServeSession:__computeInitialPatch(serverInfo)
for _ in pairs(self.__instanceMap.fromIds) do
hydratedCount += 1
end
Log.trace("[TIMING] InstanceMap contains {} entries after hydration", hydratedCount)
Log.debug("[TIMING] InstanceMap contains {} entries after hydration", hydratedCount)
-- Calculate the initial patch to apply to the DataModel to catch us
-- up to what Rojo thinks the place should look like.
Log.trace("Computing changes that plugin needs to make to catch up to server...")
self:setLoadingText("Finding differences between server and Studio...")
local diffClock = os.clock()
Log.trace("[TIMING] reconciler:diff() starting")
Log.debug("[TIMING] reconciler:diff() starting")
local success, catchUpPatch =
self.__reconciler:diff(readResponseBody.instances, serverInfo.rootInstanceId, serverInfo)
Log.trace(
Log.debug(
"[TIMING] reconciler:diff() completed ({} ms)",
string.format("%.1f", (os.clock() - diffClock) * 1000)
)
@ -741,7 +741,7 @@ function ServeSession:__computeInitialPatch(serverInfo)
for _ in pairs(catchUpPatch.added) do
addedCount += 1
end
Log.trace(
Log.debug(
"[TIMING] Diff result: {} removals, {} additions, {} updates",
#catchUpPatch.removed,
addedCount,
@ -778,9 +778,9 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
self.__confirmingPatch = catchUpPatch
local confirmWaitClock = os.clock()
Log.trace("[TIMING] Waiting for user confirmation...")
Log.debug("[TIMING] Waiting for user confirmation...")
userDecision = self.__userConfirmCallback(self.__instanceMap, catchUpPatch, serverInfo)
Log.trace(
Log.debug(
"[TIMING] User confirmation received: {} ({} ms wait)",
tostring(userDecision),
string.format("%.1f", (os.clock() - confirmWaitClock) * 1000)
@ -808,9 +808,9 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
self:__setStatus(Status.Connected, serverInfo.projectName)
self:__applyGameAndPlaceId(serverInfo)
local applyPatchClock = os.clock()
Log.trace("[TIMING] __applyPatch() starting (Accept path)")
Log.debug("[TIMING] __applyPatch() starting (Accept path)")
self:__applyPatch(catchUpPatch)
Log.trace(
Log.debug(
"[TIMING] __applyPatch() completed ({} ms)",
string.format("%.1f", (os.clock() - applyPatchClock) * 1000)
)
@ -982,9 +982,9 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
#pushPatch.updated
)
local pushClock = os.clock()
Log.trace("[TIMING] __applyPatch() starting (Confirm push path)")
Log.debug("[TIMING] __applyPatch() starting (Confirm push path)")
self:__applyPatch(pushPatch)
Log.trace(
Log.debug(
"[TIMING] __applyPatch() completed ({} ms)",
string.format("%.1f", (os.clock() - pushClock) * 1000)
)
@ -1015,9 +1015,9 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo)
Log.info("Requesting git stage for {} files", #stageIds)
end
local writeClock = os.clock()
Log.trace("[TIMING] ApiContext:write() starting (pull patch)")
Log.debug("[TIMING] ApiContext:write() starting (pull patch)")
return self.__apiContext:write(pullPatch, stageIds):andThen(function(...)
Log.trace(
Log.debug(
"[TIMING] ApiContext:write() completed ({} ms)",
string.format("%.1f", (os.clock() - writeClock) * 1000)
)

View file

@ -84,7 +84,7 @@ fn git_changed_files_impl(
let diff_base = initial_head.unwrap_or("HEAD");
let base_tree_id = resolve_tree_id(repo, diff_base);
let head_tree_id = resolve_tree_id(repo, "HEAD");
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: resolve_tree_id {}ms",
t.elapsed().as_millis()
);
@ -104,7 +104,7 @@ fn git_changed_files_impl(
collect_tree_diff_paths(repo, &base_tree, &head_tree, &mut tracked);
}
}
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: collect_tree_diff_paths {}ms ({} found)",
t.elapsed().as_millis(),
tracked.len()
@ -117,7 +117,7 @@ fn git_changed_files_impl(
if let Ok(index) = repo.open_index() {
let t = Instant::now();
collect_tree_index_changes(repo, base_id, &index, &mut tracked);
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: collect_tree_index_changes {}ms",
t.elapsed().as_millis()
);
@ -125,7 +125,7 @@ fn git_changed_files_impl(
let t = Instant::now();
let before = tracked.len();
collect_index_worktree_changes(repo, &index, &mut tracked, relevant_prefixes);
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: collect_index_worktree_changes {}ms ({} entries, {} worktree-dirty)",
t.elapsed().as_millis(),
index.entries().len(),
@ -139,7 +139,7 @@ fn git_changed_files_impl(
let t = Instant::now();
let before = tracked.len();
collect_index_worktree_changes(repo, &index, &mut tracked, relevant_prefixes);
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: collect_index_worktree_changes (no tree) {}ms ({} entries, {} worktree-dirty)",
t.elapsed().as_millis(),
index.entries().len(),
@ -149,7 +149,7 @@ fn git_changed_files_impl(
let t = Instant::now();
collect_untracked_files(repo, &mut untracked, relevant_prefixes);
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: collect_untracked_files {}ms ({} found)",
t.elapsed().as_millis(),
untracked.len()
@ -807,7 +807,7 @@ pub fn compute_git_metadata(
};
}
};
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: open_repo {}ms",
t.elapsed().as_millis()
);
@ -825,7 +825,7 @@ pub fn compute_git_metadata(
}
dirs
};
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: extract_relevant_prefixes {}ms ({} dirs)",
t.elapsed().as_millis(),
relevant_prefixes.len()
@ -835,7 +835,7 @@ pub fn compute_git_metadata(
let changed_files = match git_changed_files_impl(&repo, initial_head, &relevant_prefixes) {
Some(files) => files,
None => {
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: total {}ms (no changed files)",
total_t.elapsed().as_millis()
);
@ -846,7 +846,7 @@ pub fn compute_git_metadata(
};
}
};
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: git_changed_files_impl {}ms ({} tracked, {} untracked)",
t.elapsed().as_millis(),
changed_files.tracked.len(),
@ -854,7 +854,7 @@ pub fn compute_git_metadata(
);
if changed_files.is_empty() {
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: total {}ms (empty changeset)",
total_t.elapsed().as_millis()
);
@ -899,7 +899,7 @@ pub fn compute_git_metadata(
result
};
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: tree resolution {}ms ({} changed -> {} resolved)",
t.elapsed().as_millis(),
all_changed.len(),
@ -958,7 +958,7 @@ pub fn compute_git_metadata(
let t = Instant::now();
let batch_hashes = git_batch_check_hashes_impl(&repo, &object_refs);
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: batch_check_hashes {}ms ({} refs)",
t.elapsed().as_millis(),
object_refs.len()
@ -986,7 +986,7 @@ pub fn compute_git_metadata(
}
}
log::trace!(
log::debug!(
"[TIMING] compute_git_metadata: total {}ms ({} changed_ids, {} script_hashes, {} new_file_ids)",
total_t.elapsed().as_millis(),
changed_ids.len(),

View file

@ -417,7 +417,7 @@ impl ApiService {
})
.await
.ok();
log::trace!(
log::debug!(
"[TIMING] handle_api_rojo: compute_git_metadata {}ms",
t.elapsed().as_millis()
);
@ -426,7 +426,7 @@ impl ApiService {
None
};
log::trace!(
log::debug!(
"[TIMING] handle_api_rojo: total {}ms",
handler_start.elapsed().as_millis()
);