diff --git a/plugin/src/ApiContext.lua b/plugin/src/ApiContext.lua index 51035162..b2e7027c 100644 --- a/plugin/src/ApiContext.lua +++ b/plugin/src/ApiContext.lua @@ -164,9 +164,22 @@ end function ApiContext:connect() local url = ("%s/api/rojo"):format(self.__baseUrl) + local connectClock = os.clock() + Log.trace("[TIMING] ApiContext:connect() GET {} starting", url) return Http.get(url) + :andThen(function(response) + Log.trace( + "[TIMING] ApiContext:connect() HTTP response received ({:.1} ms)", + (os.clock() - connectClock) * 1000 + ) + return response + end) :andThen(rejectFailedRequests) :andThen(Http.Response.msgpack) + :andThen(function(body) + Log.trace("[TIMING] ApiContext:connect() msgpack decoded") + return body + end) :andThen(rejectWrongVersion) :andThen(rejectWrongFork) :andThen(function(body) @@ -177,6 +190,11 @@ function ApiContext:connect() :andThen(rejectWrongPlaceId) :andThen(function(body) self.__sessionId = body.sessionId + Log.trace( + "[TIMING] ApiContext:connect() fully validated ({:.1} ms), sessionId={}", + (os.clock() - connectClock) * 1000, + body.sessionId + ) return body end) @@ -185,15 +203,39 @@ end function ApiContext:read(ids) local url = ("%s/api/read/%s"):format(self.__baseUrl, table.concat(ids, ",")) - return Http.get(url):andThen(rejectFailedRequests):andThen(Http.Response.msgpack):andThen(function(body) - if body.sessionId ~= self.__sessionId then - return Promise.reject("Server changed ID") - end + local readClock = os.clock() + Log.trace("[TIMING] ApiContext:read() GET {} starting ({} ids)", url, #ids) + return Http.get(url) + :andThen(function(response) + Log.trace( + "[TIMING] ApiContext:read() HTTP response received ({:.1} ms, {} bytes)", + (os.clock() - readClock) * 1000, + if response.body then #response.body else 0 + ) + return response + end) + :andThen(rejectFailedRequests) + :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) + end) + :andThen(function(body) + if body.sessionId ~= self.__sessionId then + return Promise.reject("Server changed ID") + end - assert(validateApiRead(body)) + assert(validateApiRead(body)) + Log.trace("[TIMING] ApiContext:read() fully completed ({:.1} ms)", (os.clock() - readClock) * 1000) - return body - end) + return body + end) end function ApiContext:write(patch, stageIds) @@ -282,11 +324,18 @@ 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) return Promise.new(function(resolve, reject) + local wsClock = os.clock() local success, wsClient = pcall(HttpService.CreateWebStreamClient, HttpService, Enum.WebStreamClientType.WebSocket, { Url = url, }) + Log.trace( + "[TIMING] WebSocket CreateWebStreamClient ({:.1} ms, success={})", + (os.clock() - wsClock) * 1000, + success + ) if not success then reject("Failed to create WebSocket client: " .. tostring(wsClient)) return diff --git a/plugin/src/App/init.lua b/plugin/src/App/init.lua index e002b79e..62ab301f 100644 --- a/plugin/src/App/init.lua +++ b/plugin/src/App/init.lua @@ -1002,14 +1002,14 @@ function App:startSession() self:setState({ connectingText = "Computing diff view...", }) + local patchTreeClock = os.clock() + 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) self:setState({ appStatus = AppStatus.Confirming, - patchTree = PatchTree.build( - patch, - instanceMap, - { "Property", "Current", "Incoming" }, - serverInfo.gitMetadata - ), + patchTree = patchTree, confirmData = { serverInfo = serverInfo, }, @@ -1021,6 +1021,7 @@ function App:startSession() timeout = 7, }) + Log.trace("[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 61648f77..afb79e3b 100644 --- a/plugin/src/Reconciler/applyPatch.lua +++ b/plugin/src/Reconciler/applyPatch.lua @@ -19,6 +19,8 @@ local reifyInstance, applyDeferredRefs = reify.reifyInstance, reify.applyDeferre local setProperty = require(script.Parent.setProperty) local function applyPatch(instanceMap, patch) + local applyPatchClock = os.clock() + -- Tracks any portions of the patch that could not be applied to the DOM. local unappliedPatch = PatchSet.newEmpty() @@ -40,6 +42,14 @@ local function applyPatch(instanceMap, patch) ) end + Log.trace( + "[TIMING] applyPatch() starting: {} removals, {} additions, {} updates", + #patch.removed, + addCount, + #patch.updated + ) + + local removalClock = os.clock() for _, removedIdOrInstance in ipairs(patch.removed) do -- Skip auto-created instances that shouldn't be synced local instance = if Types.RbxId(removedIdOrInstance) @@ -67,6 +77,8 @@ local function applyPatch(instanceMap, patch) end end + Log.trace("[TIMING] applyPatch() removals completed ({:.1} ms)", (os.clock() - removalClock) * 1000) + -- Detect echoed additions from DescendantAdded handler. -- When the plugin pre-inserts instances with temp IDs and the server -- broadcasts the same instances with real Refs, remap the InstanceMap @@ -100,6 +112,8 @@ local function applyPatch(instanceMap, patch) end end + local additionClock = os.clock() + Log.trace("[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 @@ -146,6 +160,10 @@ local function applyPatch(instanceMap, patch) end end + Log.trace("[TIMING] applyPatch() additions completed ({:.1} ms)", (os.clock() - additionClock) * 1000) + + local updateClock = os.clock() + Log.trace("[TIMING] applyPatch() updates starting ({} updates)", #patch.updated) for _, update in ipairs(patch.updated) do local instance = instanceMap.fromIds[update.id] @@ -314,7 +332,14 @@ local function applyPatch(instanceMap, patch) end end + Log.trace("[TIMING] applyPatch() updates completed ({:.1} ms)", (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() total completed ({:.1} ms)", (os.clock() - applyPatchClock) * 1000) return unappliedPatch end diff --git a/plugin/src/Reconciler/diff.lua b/plugin/src/Reconciler/diff.lua index 95e8a25a..52d6f811 100644 --- a/plugin/src/Reconciler/diff.lua +++ b/plugin/src/Reconciler/diff.lua @@ -59,8 +59,15 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo) updated = {}, } + local diffClock = os.clock() local diffCount = 0 + local virtualCount = 0 + for _ in pairs(virtualInstances) do + virtualCount += 1 + end + Log.trace("[TIMING] diff() starting ({} virtual instances to diff)", virtualCount) + -- Build a lookup table for visible services (for ignoreHiddenServices check) local visibleServicesSet: { [string]: boolean } = {} if serverInfo and serverInfo.ignoreHiddenServices and serverInfo.visibleServices then @@ -247,6 +254,19 @@ local function diff(instanceMap, virtualInstances, rootId, serverInfo) return false, err end + local addedCount = 0 + for _ in pairs(patch.added) do + addedCount += 1 + end + Log.trace( + "[TIMING] diff() completed: {} instances diffed, {} removals, {} additions, {} updates ({:.1} ms)", + diffCount, + #patch.removed, + addedCount, + #patch.updated, + (os.clock() - diffClock) * 1000 + ) + return true, patch end diff --git a/plugin/src/Reconciler/hydrate.lua b/plugin/src/Reconciler/hydrate.lua index e434483d..5f1e50e4 100644 --- a/plugin/src/Reconciler/hydrate.lua +++ b/plugin/src/Reconciler/hydrate.lua @@ -16,12 +16,15 @@ local Matching = require(script.Parent.matching) local HYDRATE_YIELD_INTERVAL = 1000 local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, session) + local isRoot = not session or not session.hydrateCount + if not session then session = Matching.newSession() end if not session.hydrateCount then session.hydrateCount = 0 + session.hydrateClock = os.clock() end session.hydrateCount += 1 if session.hydrateCount % HYDRATE_YIELD_INTERVAL == 0 then @@ -34,6 +37,10 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess invariant("Cannot hydrate an instance not present in virtualInstances\nID: {}", rootId) end + if isRoot then + Log.trace("[TIMING] hydrate() starting at root '{}' ({})", virtualInstance.Name, rootInstance:GetFullName()) + end + instanceMap:insert(rootId, rootInstance) local existingChildren = rootInstance:GetChildren() @@ -54,8 +61,21 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess end end + local matchClock = os.clock() local result = Matching.matchChildren(session, validVirtualIds, existingChildren, virtualInstances, rootId, rootInstance) + local matchElapsed = (os.clock() - matchClock) * 1000 + + if matchElapsed > 10 then + Log.trace( + "[TIMING] matchChildren for '{}' took {:.1} ms ({} virtual, {} studio, {} matched)", + virtualInstance.Name, + matchElapsed, + #validVirtualIds, + #existingChildren, + #result.matched + ) + end -- Recursively hydrate matched pairs for _, pair in result.matched do @@ -75,6 +95,15 @@ local function hydrate(instanceMap, virtualInstances, rootId, rootInstance, sess ) end end + + if isRoot then + Log.trace( + "[TIMING] hydrate() completed: {} instances processed, {} matched ({:.1} ms total)", + session.hydrateCount, + #result.matched, + (os.clock() - session.hydrateClock) * 1000 + ) + end end return hydrate diff --git a/plugin/src/ServeSession.lua b/plugin/src/ServeSession.lua index 2d0d892a..661c0f28 100644 --- a/plugin/src/ServeSession.lua +++ b/plugin/src/ServeSession.lua @@ -329,9 +329,13 @@ function ServeSession:start() self:__setStatus(Status.Connecting) self:setLoadingText("Connecting to server...") + local sessionStartClock = os.clock() + Log.trace("[TIMING] ServeSession:start() begun") + self.__apiContext :connect() :andThen(function(serverInfo) + Log.trace("[TIMING] ApiContext:connect() completed ({:.1} ms)", (os.clock() - sessionStartClock) * 1000) self:setLoadingText("Loading initial data from server...") -- Configure sync mode based on server capabilities @@ -342,9 +346,18 @@ function ServeSession:start() self.__changeBatcher:setSyncScriptsOnly(self.__syncScriptsOnly) self.__serverInfo = serverInfo + + local computePatchClock = os.clock() + Log.trace("[TIMING] __computeInitialPatch() starting") return self:__computeInitialPatch(serverInfo):andThen(function(catchUpPatch) + Log.trace( + "[TIMING] __computeInitialPatch() completed ({:.1} ms)", + (os.clock() - computePatchClock) * 1000 + ) self:setLoadingText("Starting sync loop...") + local wsClock = os.clock() + Log.trace("[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 @@ -360,12 +373,22 @@ function ServeSession:start() self:__stopInternal(err) end end) + Log.trace("[TIMING] connectWebSocket() initiated ({:.1} ms)", (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) + return self:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo):andThen(function(...) + Log.trace( + "[TIMING] __confirmAndApplyInitialPatch() completed ({:.1} ms)", + (os.clock() - confirmClock) * 1000 + ) + return ... + end) end) end) :andThen(function() + Log.trace("[TIMING] ServeSession:start() total elapsed ({:.1} ms)", (os.clock() - sessionStartClock) * 1000) -- Initial sync is fully complete (including any writes to the server) if self.__initialSyncCompleteCallback ~= nil then self.__initialSyncCompleteCallback() @@ -568,7 +591,14 @@ function ServeSession:__applyPatch(patch) Timer.stop() self.__applyingPatch = true + local reconcilerClock = os.clock() + 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, + patchApplySuccess + ) if not patchApplySuccess then self.__applyingPatch = false if historyRecording then @@ -579,8 +609,10 @@ function ServeSession:__applyPatch(patch) error(unappliedPatch) end + 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)") -- Some changes did not apply, let's try replacing them instead local addedIdList = PatchSet.addedIdList(unappliedPatch) local updatedIdList = PatchSet.updatedIdList(unappliedPatch) @@ -607,6 +639,7 @@ function ServeSession:__applyPatch(patch) end end) self.__applyingPatch = false + Log.trace("[TIMING] Sync fallback phase completed ({:.1} ms)", (os.clock() - fallbackClock) * 1000) if not fallbackOk then Log.warn("Sync fallback errored: {}", fallbackErr) @@ -638,7 +671,17 @@ function ServeSession:__applyPatch(patch) end 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) + + local instanceCount = 0 + for _ in pairs(readResponseBody.instances) do + instanceCount += 1 + end + Log.trace("[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. self.__apiContext:setMessageCursor(readResponseBody.messageCursor) @@ -647,20 +690,43 @@ function ServeSession:__computeInitialPatch(serverInfo) -- tracking them in the reconciler. 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) 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) + + local hydratedCount = 0 + for _ in pairs(self.__instanceMap.fromIds) do + hydratedCount += 1 + end + Log.trace("[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") local success, catchUpPatch = self.__reconciler:diff(readResponseBody.instances, serverInfo.rootInstanceId, serverInfo) + Log.trace("[TIMING] reconciler:diff() completed ({:.1} ms)", (os.clock() - diffClock) * 1000) if not success then Log.error("Could not compute a diff to catch up to the Rojo server: {:#?}", catchUpPatch) end + local addedCount = 0 + for _ in pairs(catchUpPatch.added) do + addedCount += 1 + end + Log.trace( + "[TIMING] Diff result: {} removals, {} additions, {} updates", + #catchUpPatch.removed, + addedCount, + #catchUpPatch.updated + ) + for _, update in catchUpPatch.updated do if update.id == self.__instanceMap.fromInstances[game] and update.changedClassName ~= nil then -- Non-place projects will try to update the classname of game from DataModel to @@ -690,7 +756,14 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) self.__isConfirming = true self.__confirmingPatch = catchUpPatch + local confirmWaitClock = os.clock() + Log.trace("[TIMING] Waiting for user confirmation...") userDecision = self.__userConfirmCallback(self.__instanceMap, catchUpPatch, serverInfo) + Log.trace( + "[TIMING] User confirmation received: {} ({:.1} ms wait)", + tostring(userDecision), + (os.clock() - confirmWaitClock) * 1000 + ) -- Clear confirmation state flags self.__confirmingPatch = nil @@ -713,7 +786,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) -- Legacy: Accept all changes (push all to Studio) self:__setStatus(Status.Connected, serverInfo.projectName) self:__applyGameAndPlaceId(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) return Promise.resolve() elseif type(userDecision) == "table" and userDecision.type == "Confirm" then -- New: Apply based on per-item selections @@ -881,7 +957,10 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) #pushPatch.removed, #pushPatch.updated ) + 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) end if Settings:get("oneShotSync") then @@ -908,7 +987,12 @@ function ServeSession:__confirmAndApplyInitialPatch(catchUpPatch, serverInfo) if hasStageIds then Log.info("Requesting git stage for {} files", #stageIds) end - return self.__apiContext:write(pullPatch, stageIds) + 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) + return ... + end) end return Promise.resolve()