Bound the packaged remote extension-host Ready-to-Initialized handshake

[wieslawsoltes]

Parent: #81
Related downstream qualification: #280 and #252.
Adjacent but non-overlapping lifetime owner: #288.
Local diagnostic commit (not pushed): e6f5c6a in vscode-demo.

Proven boundary

An unchanged packaged Code OSS workspace run on WebScene base aa786c0e (with the local #287 measurement candidate 0f92cf47), AppScene 1420e227, Code OSS 645f29cc, and Node 24.18.1 retained every browser and native phase of extension-host startup.

The local iframe/Worker/transferred-MessagePort path completes promptly after its document is dispatched:

• iframe resource fetch: 0.835 ms, 6,786 bytes
• iframe append → document loaded: 1,189 ms
• document loaded → Worker created: 8 ms
• Worker created → transferred MessagePort: 130 ms
• transferred port → first message: 2 ms
• first port message → Ready: 1 ms
• local Ready → Initialized: 708 ms
• worker module resource fetch: 2.964 ms, 1,932,148 bytes

The remote extension-host path is the first distinct handshake breach:

• transport connected → first protocol byte / Ready: 1,177 ms
• Ready → Initialized: 4,379 ms
• remote Initialized → the separate AgentHost service connection: 9,682 ms
• AgentHost service connection → exact five-row Explorer result: 99 ms

The exact root, provider registration, five resolved children, five Explorer-model children, and five rendered rows all pass. The 2 s product bound fails. The run observed 146 FileReader reads / 13,120,521 bytes with a 14,767 ms maximum, while the underlying Blob conversion maximum was 0.038 ms. This points to delayed asynchronous protocol continuation rather than resource transfer or port transfer.

Observer bounds were 21/96 phase records with zero drops and 8/64 resource records. Peak app process-group RSS was 845,184 KiB. App/server/helper processes were terminated and verified absent after the bounded run.

Retained evidence:

• /private/tmp/vscode-252-product-extension-host-81.log
• /private/tmp/vscode-252-extension-host-81-evidence.json (SHA-256 1a53ca07dfa317aa7fdfcd6b598617e8cfd41105770e9ad7fe082dac1172e851)

Scope

Identify and fix the product-neutral scheduler/protocol boundary that delays the packaged remote extension host between connected transport, Ready, initialization-data delivery, and Initialized. Keep Code OSS source unchanged outside query-gated diagnostics.

This issue does not change MessagePort lifetime ownership in #288. That issue still owns forced-GC reachability; this trace shows the transferred port, first message, Ready, and Initialized all arrive in order.

Acceptance

• A reduced browser oracle and the native runtime retain timestamps for transport connected, first protocol byte, Ready, initialization-data send/settlement, Initialized, cancellation, reconnect, and teardown.
• Direct native/provider and unchanged Chromium runs distinguish socket receive, runtime task delivery, Promise/microtask continuation, protocol dispatch, and init-data serialization/handling.
• Cold and warm runs keep transport → Ready and Ready → Initialized each within 500 ms p95, and the complete remote handshake within 1 s p95, across at least 20 cycles.
• Competing WebSocket, FileReader, Worker, MessagePort, timer, and microtask traffic remains fair; queue high-water and wake counts are retained and bounded.
• Cancellation before Ready, cancellation during init-data creation, reconnect, navigation, Worker termination, socket close, and engine teardown release callbacks, ports, queues, and wake registrations exactly once.
• The unchanged Code OSS exact-root/five-child/five-row Qualify remote workspace bootstrap, Explorer contents, and watcher refresh #252 gate completes within 2 s without polling or product behavior changes.
• V8 heap and RSS plateau after warm-up; no retained protocol buffers, tasks, ports, or documents remain after teardown.
• Directly related macOS/Linux/Windows native gates and the browser oracle pass.

[wieslawsoltes]

Packaged receiver-boundary trace on unchanged Code OSS 645f29cc, AppScene 1420e227, exact Node 24.18.1, and the current diagnostic package now separates the 4.2 s remote Ready → Initialized interval.

Second workspace document:

• remote transport connected → Ready: 1,288.17 ms
• Ready → next Promise microtask: 0.116 ms
• _createExtHostInitData() settle: 426.90 ms
• JSON + UTF-8 serialization: 8.61 ms for 1,071,424 bytes
• init-data send → remote Initialized: 3,788.40 ms
• total Ready → Initialized: 4,224.01 ms

Resource delivery remains fast: the iframe response was 0.899 ms / 6,786 bytes and the worker module response was 2.803 ms / 1,932,148 bytes. The exact selected URI/root, provider registration, five resolved/model children, five rendered rows, and 64 maximum Explorer DOM nodes all passed functionally. Peak app process-group RSS was 837,376 KiB. The bounded run terminated its complete process group and verification found no app/server/helper descendants.

The independent 20-cycle native product-neutral oracle is also fast (Ready p95 5.944 ms; Initialized p95 5.408 ms; socket dispatch p95 5 ms; FileReader p95 2.536 ms; Promise/microtask p95 0.0078 ms; serialization p95 0.213 ms). Chromium passes the same 43/43 contract (Ready and Initialized p95 1.7 ms). Therefore no generic WebScene implementation is justified from this evidence yet. The next trace must split the receiver side after the 1.07 MB init payload is sent: receipt/parse, init-data hydration, extension scan/activation, and Initialized response.

Retained evidence:

• product log: /private/tmp/vscode-252-product-handshake-289.log
• product log SHA-256: d85db2b31883b5f5f7e3a6747de96945c1810e792b0293a03df104a5dee0b761
• process/RSS summary: /private/tmp/vscode-252-product-handshake-289-process.txt
• native oracle: /private/tmp/webscene-289-baseline.log
• Chromium oracle: /private/tmp/webscene-289-chrome-baseline-verify/results.json
• query-gated local vscode-demo observer commit (not pushed): 10fc9aa

[wieslawsoltes]

Receiver-side instrumentation isolates the breach before Node parsing or extension initialization.

On the retained second workspace document:

• Node remote extension host sent Ready at 1789658968549
• WebScene browser received Ready at 1789658969571: 1,022 ms inbound delivery
• WebScene serialized and sent the 1,071,425-byte init message at 1789658969991
• Node remote extension host received that exact 1,071,425-byte message at 1789658973482: 3,491 ms outbound browser → Node delivery
• receiver UTF-8 decode: 0.133 ms
• receiver JSON parse: 3.589 ms
• total receiver hydrate/watchdog work before Initialized: 12.204 ms
• Node sent Initialized at 1789658973495
• WebScene browser received Initialized at 1789658973588: 93 ms return delivery

ExtensionHostMain construction begins only after Initialized is sent, so extension scanning/activation cannot own the Ready → Initialized breach. The exact root/provider/five resolved children/five model children/five rendered rows/64-node result still passes functionally. The 50 s bounded observer waited for the later constructor completion marker, then terminated the complete process group; no app/server/extension-host descendants remained. Peak process-group RSS was 843,184 KiB.

A size-matched control preserves the earlier fast baseline: the product-neutral native oracle sends a binary-compatible 1,071,424-byte payload for 20 cycles and reports Initialized p95 6.140 ms; Chromium passes 43/43 in 89 ms. The next reduced gate must add the actual Code OSS binary framing/compression and concurrent traffic/queue shape, retain enqueue → wire → server-receipt timing, and preserve this fast size-only control before any WebScene implementation.

Retained evidence:

• app log: /private/tmp/vscode-252-product-receiver-289.log (SHA-256 51d5b4d696b5474e2210a1f13851b39531443030927fa148f6705ffc79aed160)
• server/receiver log: /private/tmp/vscode-252-product-receiver-289-server.log (SHA-256 372b41c577260eb7787ceeaaca6c7f6655ced1259f4a4d4e9715e6280cf2e9db)
• process/RSS summary: /private/tmp/vscode-252-product-receiver-289-process.txt
• matched-size native control: /private/tmp/webscene-289-one-mib.log
• matched-size Chromium control: /private/tmp/webscene-289-chrome-one-mib-2/results.json
• local query-gated receiver observer commit (not pushed): da9db1a

[wieslawsoltes]

The actual browser WebSocket send boundary rejects the earlier wire-delay hypothesis and moves the earliest breach into the deferred Code OSS protocol-writer flush.

Exact second-document timestamps:

• protocol.send(...) returned after init serialization at 1789659699540
• native WebSocket.send entered at 1789659703082: 3,542 ms later
• WebSocket.send returned in 0.743 ms, with bufferedAmount 0 before and after
• its next Promise microtask ran at 0.788 ms, still with bufferedAmount 0
• Node received the framed payload at 1789659703087: 5 ms after actual WebSocket send
• Node decode/parse/hydrate completed in 14.55 ms
• Node sent Initialized at 1789659703101; the browser received it at 1789659703467: 366 ms later

Pinned Code OSS ProtocolWriter._scheduleWriting() coalesces writes behind a zero-delay timer. This run shows that timer-backed flush, rather than JSON serialization, native WebSocket enqueue, loopback wire delivery, Node parsing, or extension scanning, owns nearly all of the Ready → Initialized breach.

The product-shaped control now uses a 13-byte IPC header, 1,071,425-byte binary body, 200 competing 64 KiB inbound frames per cycle, a shared FileReader queue, and 20 cycles. Direct native send remains fast (outbound p95 1 ms, send return p95 0.708 ms, drain p95 0.004 ms, receive-queue HWM 199). A deferred flush under a single independently paced WebSocket source also remains fast (flush timer p95 0.019 ms). The remaining reduction must model the product's combined/coalesced protocol writer plus simultaneous Worker, MessagePort, and multiple WebSocket task sources; no runtime fix is proposed yet.

The bounded run reached exact root/provider/five-child/five-model/five-row evidence, terminated its process group, and left no app/server/extension-host descendants. Peak group RSS was 845,648 KiB.

Retained evidence:

• app log: /private/tmp/vscode-252-product-websocket-send-289.log (SHA-256 52296aa1c97c11c8c696577e7a0cb0dd27e2605a4a9c8fe26ee8f225ddb64ef5)
• server log: /private/tmp/vscode-252-product-websocket-send-289-server.log (SHA-256 4b6c06cf87e5e709431486b64d5920ca76041821290d0bea93f5297f85411228)
• process/RSS summary: /private/tmp/vscode-252-product-websocket-send-289-process.txt
• direct product-shaped oracle: /private/tmp/webscene-289-product-shape.log
• async paced/deferred control: /private/tmp/webscene-289-paced-async-deferred-flush.log
• local query-gated observer commit (not pushed): 4c7c662

[wieslawsoltes]

The reduced multi-source oracle now proves that #289's Ready→Initialized breach is owned by generic timer-vs-async task fairness in #287.

On exact merged-#245 main 4040058e, the actual 13-byte framing + 1,071,425-byte initialization body waits 3,581.35 ms from ProtocolWriter's coalesced zero-delay timer to the real WebSocket.send call while Worker/MessagePort/WebSocket work remains ready and the FileReader queue ages. The send itself takes 0.743 ms in the retained product trace and Node receives it 5 ms later, so this is not a wire-delay or serialization defect.

The identical 20-cycle oracle with the local #287 arbitration candidate passes at 0.1539 ms max / 0.0475 ms p95, with Initialized p95 12.27 ms. Chromium passes 45/45 with about 0.1 ms timer p95/max. Local combined implementation/oracle commit 26694871 remains unpushed pending #281's four-source ServiceWorker rotation merge and rebase.

Detailed counts, queue bounds, memory/work bounds, logs, and SHA-256 values are retained on #287.

[wieslawsoltes]

Exact unchanged-Code product rejection after rebasing the reduced candidate onto WebScene main 1bd8596e3dc07a3281204504acad379eb1f6bc78 (b75d37958ef7ce3f73a5b08de6b0516b0f8f57eb, local/unpushed):

Phase	Timestamp / duration
Remote transport connected	1789661803245
Ready / first protocol message	1789661803717
Initialization data created	1789661804058 (340.689 ms)
Serialized	1789661804066 (8.786 ms, 1,071,424 bytes)
Protocol send requested	1789661804067
Native WebSocket.send entered	1789661807765 (+3698 ms)
Native send returned	0.783 ms
Send microtask	0.834 ms, bufferedAmount=0
Remote Initialized	1789661807949 (Ready→Initialized ~4232 ms)

The same candidate passes the reduced product-neutral oracle (exact-main max 3617.66 ms → candidate max 0.204 ms), but that arbitration is not sufficient in the packaged product. The remaining owner lies in another task tier before native WebSocket.send; wire/server/receiver work is still fast once the send begins. No PR is being opened.

The workspace reached the exact vscode-remote root, resolved the expected five children, and rendered five Explorer rows, but the observer correctly reported status=failed because the two-second performance contract was missed. Query-gated diagnostics only; unchanged Code OSS source. App/server/extension-host/watcher/agent descendants were terminated; port 54759 has no listener. App RSS at capture was 557,840 KiB and the observed process tree totaled 1,181,904 KiB.

Evidence log: /private/tmp/vscode-252-product-b75d3795.log, SHA-256 f58b40413fe5dd30567d0d6a3d207b668fd07bea96b594aae9c5568509a38252.

[wieslawsoltes]

The focused #293 candidate b485f6aa passes its 20-cycle reduced window-message/timer oracle (max 0.323 ms) but does not move the unchanged packaged-Code boundary: protocol-send request → native WebSocket.send remains 3478 ms, followed by a 0.815 ms send and 0.857 ms microtask. Ready→Initialized remains ~4102 ms.

This excludes the async-message group and window.postMessage as sufficient owners. Another runtime tier before due timers, or the condition that makes the protocol writer's timer eligible, still owns the delay. No push/PR; draft #292 remains a path collision.

Evidence and cleanup: /private/tmp/vscode-252-product-b485f6aa.log, SHA-256 cb9b7c5c843da4badc2b8c7e35c2850b41598c70b7510afce7c94bee5b5a2a26; all descendants terminated and port 56322 free.

[wieslawsoltes]

The corrected runtime-gated task-source trace changes the remaining owner and rejects the queue-arbitration candidates as sufficient fixes.

Exact packaged evidence

• source observer commit: local/unpushed a50fd344;
• trace: /private/tmp/vscode-252-task-arbitration-a50fd344.log;
• SHA-256: 0e0ac7d890bc6fe664ed6efa3054919aff932cc38cc9a607d906db073aa495a6;
• protocol timer: one-shot timerId=1194, requested at 50 ms, fired 3,051.582 ms overdue;
• work before it fired: one synchronous fetch task held the runtime for 2,805.749 ms, followed by window-message work for 236.403 ms;
• the measured async task and platform drains were only 0.035 ms and 0.002 ms;
• protocol send scheduling → native send: 3,637 ms;
• native send itself: 0.771 ms, microtask checkpoint 0.836 ms, and Initialized followed 125 ms later;
• app RSS: 684,800 KiB; process-tree RSS: 1,200,496 KiB;
• all app/server processes were terminated and the diagnostic port was released.

The active investigation now instruments drain_fetch_task response construction, settlement, and its promise/microtask continuation. The reduced native response/header/cookie oracle is sub-millisecond; one bounded packaged trace with both task-source and fetch-phase probes is scheduled. No scheduler candidate will be pushed unless it passes the unchanged packaged product gate.

[wieslawsoltes]

The corrected runtime-env-gated task/fetch trace isolates the remaining #289 owner to the promise continuation for built-in theme loading; it is no longer a scheduler/wire ambiguity.

For extensions/theme-defaults/themes/light_vs.json (7,407 bytes, status 200):

• total fetch task: 2457.000 ms
• selection/future/body+headers/promise settlement: 0.014 ms combined
• PerformMicrotaskCheckpoint: 2424.455 ms
• style batch finish: 32.530 ms

The corresponding 50 ms timer was overdue 2459.903 ms, attributed to fetch 2457.097 ms; async message was 0.034 ms, window message 0.107 ms, and platform pumping 0.002 ms. Protocol-send request → native send remained 3268 ms; native send 0.677 ms and its microtask 0.716 ms.

Browser semantics require the promise microtask checkpoint to complete before the next timer task, so queue arbitration must not preempt it. Opened focused downstream performance issue #297 for the theme continuation/DOM-CSS hot path; no runtime behavior change or scheduler PR is proposed from this trace.

Observer commits a50fd344 and 7ad62971 remain local/unpushed. Evidence: /private/tmp/vscode-252-fetch-phases-7ad62971.log, SHA-256 d1feb5b7970d56298ee80c2a49228dfc3060c4663dec3a2249b09e77c4d98b72. Full descendant and port cleanup verified.

[wieslawsoltes]

Fresh exact-package confirmation from AppScene f52fb46b / WebScene 348ea440 / unchanged Code OSS 645f29cc keeps this issue ahead of reopened #252 and AppScene#131.

The authoritative absolute-folder case selected the exact remote URI and opened the new document. In its retained console timeline:

• new-document Management socket creation completed in 4 ms;
• remote AgentHost logged Initializing / Connecting at approximately 1789718069286;
• remote AgentHost logged Connected at 1789718072002, about 2.716 s later;
• Explorer subsequently rendered the exact beta/visible.txt child, but measured first-child paint was 4,594.3 ms against the 2-second Qualify remote workspace bootstrap, Explorer contents, and watcher refresh #252 gate.

Picker dialog (1,376.1 ms), post-accept handoff (486.4 ms), exact URI/options, root/child semantics, observer p95 (0.625 ms), and descendant/port cleanup pass. Runtime counters retained 1,250 late timers / 209,700 ms aggregate lateness, 193 worker waits, 178 signalled wakes, and 15 timeout wakes. This supports the existing scheduler/protocol scope here and avoids a duplicate latency issue.

Order remains #289 fix and 20-cycle handshake gates → #252 first-child rerun → remaining AppScene#131 path matrix.

[wieslawsoltes]

PR #347 now carries the focused current-main fix and regression gates.

Current-main baseline (b29684224dd2a7bff8398b82821c2803de4d43f0) with the exact same product-shaped 20-cycle oracle fails as follows:

• Initialized p95: 761 ms;
• timer-coalesced protocol flush p95: 685.926 ms, max 21,332.7 ms;
• Worker / MessagePort / window tasks before the delayed flush: 700,000 / 700,000 / 700,000;
• WebSocket tasks before flush: 62;
• wall time: 37.31 s, maximum RSS: 192,561,152 bytes.

Candidate dfe8ba07ea7465f4d145ff47b77d9bcbfd53f801 uses one task-source arbitration invariant: after any non-timer task wins while a timer is due, that timer runs before another observable task source can monopolize the loop. JavaScript task run-to-completion and the required microtask checkpoint remain unchanged.

Four focused native runs pass:

• protocol flush p95 0.116–0.282 ms, max 0.510 ms;
• Initialized p95 43.7–52.4 ms, Ready p95 8.0–8.5 ms;
• at most 2 competing tasks before flush;
• Worker / MessagePort queue high-water 1 / 1, receive/FileReader queue high-water at most 5;
• WebSocket send-return p95 23.9–26.6 ms, drain p95 0.008–0.017 ms;
• 100-cycle WebSocket cancellation/reconnect lifecycle passes;
• max RSS 128,499,712–134,070,272 bytes; the strengthened fourth run records an exact post-collection V8 heap plateau of 725,308 → 725,308 bytes;
• focused native component profile passes 45/45 assertions in 383 ms.

Retained evidence:

• baseline /private/tmp/webscene-289-baseline.log, SHA-256 03ba50b64502a441ed5b85afde115ed8ee6e0036f2ed4fe48104b2a3121fe9fa;
• candidate repeats /private/tmp/webscene-289-candidate-{1,2,3,4}.log, SHA-256 553e034f2c4870e0b73f6a94246566a8ce689211ced1a9833caca537abaacf0f, 429db81e458bc705cb1edbec2efbdf53afc0578dc2c72e680dad75ae8ce7d36d, 7791e028e54805465adbf344f7feeead458ce4fe4143ead6c7fdfdef4bca4edc, d8f33570ae8ba7ba2ebd464f1a14c342f99d9870fa5c579a6f72955582ce6fbb;
• focused profile /private/tmp/webscene-289-native-wpt-d/results.json, SHA-256 38e6ede21efbde11647d57aef9731e14e8cb2f3a5e405810be983131a21898ee.

The earlier Chromium 45/45 control remains applicable to this same contract. I did not start another browser process because the host currently has a long-running shared Chrome instance and the isolated headless runner could not obtain a separate page target. PR CI owns the cross-platform native and portable source gates. Unchanged packaged Code OSS remains the downstream #252 qualification after merge.

[wieslawsoltes]

Merged PR #347 on exact main 114f38e1.

• PR head: 3d7cfebc296b6806bfbe29a5541fe1c6897f05ec
• squash merge: dbd7351a88415d369ea322c692153474fb7a933c
• exact-head hosted gates: portable V8, Linux native, macOS native, NativeAOT 11/12, and Linux document contracts all pass;
• exact-base local rerun: protocol flush p95 0.157 ms / max 0.274 ms, Initialized p95 49.98 ms, at most 2 competing tasks, queue high-water at most 4, V8 heap 725,308 → 725,308 bytes;
• focused native browser profile: 45/45.

The Windows package job remained blocked by the pre-existing MSVC std::vector::contains errors in the untouched CSS cascade file; preceding main run 35320520086 has the identical four errors. That failure is not attributed to #347.

This issue stays open until the downstream unchanged packaged Code OSS #252 run proves the remote AgentHost interval and exact first-child paint bounds on merge dbd7351a.