diff --git a/plugin/src/ApiContext.lua b/plugin/src/ApiContext.lua index 59587586..ca3e56df 100644 --- a/plugin/src/ApiContext.lua +++ b/plugin/src/ApiContext.lua @@ -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 diff --git a/plugin/src/App/Components/StringDiffVisualizer/init.lua b/plugin/src/App/Components/StringDiffVisualizer/init.lua index 6802383c..064f0abc 100644 --- a/plugin/src/App/Components/StringDiffVisualizer/init.lua +++ b/plugin/src/App/Components/StringDiffVisualizer/init.lua @@ -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, diff --git a/plugin/src/App/init.lua b/plugin/src/App/init.lua index 8aed56e7..0a9ed3bc 100644 --- a/plugin/src/App/init.lua +++ b/plugin/src/App/init.lua @@ -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 diff --git a/plugin/src/Reconciler/applyPatch.lua b/plugin/src/Reconciler/applyPatch.lua index 326cdb34..e3d0faf8 100644 --- a/plugin/src/Reconciler/applyPatch.lua +++ b/plugin/src/Reconciler/applyPatch.lua @@ -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) ) diff --git a/plugin/src/Reconciler/diff.lua b/plugin/src/Reconciler/diff.lua index b0c506f3..48c3a57c 100644 --- a/plugin/src/Reconciler/diff.lua +++ b/plugin/src/Reconciler/diff.lua @@ -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, diff --git a/plugin/src/Reconciler/hydrate.lua b/plugin/src/Reconciler/hydrate.lua index 6230bea9..b844d43f 100644 --- a/plugin/src/Reconciler/hydrate.lua +++ b/plugin/src/Reconciler/hydrate.lua @@ -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, diff --git a/plugin/src/ServeSession.lua b/plugin/src/ServeSession.lua index 0ea37bef..5e5966ea 100644 --- a/plugin/src/ServeSession.lua +++ b/plugin/src/ServeSession.lua @@ -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) ) diff --git a/src/git.rs b/src/git.rs index a77fb073..ee7b29ae 100644 --- a/src/git.rs +++ b/src/git.rs @@ -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(), diff --git a/src/web/api.rs b/src/web/api.rs index df9714a6..974384a1 100644 --- a/src/web/api.rs +++ b/src/web/api.rs @@ -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() );