Enhance logging with detailed timing information for API and session operations

- Added timing logs to various functions in `ApiContext`, `ServeSession`, and `Reconciler` to track performance and improve debugging.
- Introduced detailed trace logs for connection, reading, writing, and patch application processes, providing insights into execution times.
- Updated the `App` component to log the patch tree building process, enhancing visibility during session startup.

These changes aim to improve performance monitoring and facilitate troubleshooting within the application.

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

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

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

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
 

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

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()