From 21eee148acc4a2bcb9856adc5ba9d7463a33f84d Mon Sep 17 00:00:00 2001 From: pmodular <282521242+pmodular@users.noreply.github.com> Date: Wed, 7 Oct 2026 00:57:29 +0900 Subject: [PATCH] webchannel: more Lens benchmark --- .../{audit.md => connection-reuse-audit.md} | 0 .../connection-reuse-audit.md | 116 ++++++++++++++++++ .../report.md | 55 +++++++++ webchannel/benchmark/lens/AGENTS.md | 2 +- webchannel/benchmark/lens/README.md | 8 +- .../benchmark/lens/run-cold-benchmark.sh | 6 +- .../lens/summarize-cold-benchmark.py | 21 ++-- .../objc/demo/WebChanneliOSDemo/README.md | 6 +- .../WebChanneliOSDemo/WebChannelService.swift | 63 ++++++---- .../LensBenchmarkTests.swift | 13 +- 10 files changed, 254 insertions(+), 36 deletions(-) rename webchannel/benchmark/lens/2026-10-08_13-39_binary-cold-20ms-rerun_JST/{audit.md => connection-reuse-audit.md} (100%) create mode 100644 webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/connection-reuse-audit.md create mode 100644 webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/report.md diff --git a/webchannel/benchmark/lens/2026-10-08_13-39_binary-cold-20ms-rerun_JST/audit.md b/webchannel/benchmark/lens/2026-10-08_13-39_binary-cold-20ms-rerun_JST/connection-reuse-audit.md similarity index 100% rename from webchannel/benchmark/lens/2026-10-08_13-39_binary-cold-20ms-rerun_JST/audit.md rename to webchannel/benchmark/lens/2026-10-08_13-39_binary-cold-20ms-rerun_JST/connection-reuse-audit.md diff --git a/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/connection-reuse-audit.md b/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/connection-reuse-audit.md new file mode 100644 index 0000000..b66b601 --- /dev/null +++ b/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/connection-reuse-audit.md @@ -0,0 +1,116 @@ +# Handshake transport audit + +[Report](report.md) · [Artifacts](artifacts.md) + +The table lists the actual handshake task, identified by its request ID. In ON trials, either the handshake GET or the concurrent early POST may create the fresh connection; the other request can reuse it within that trial. + +The early POST HTTP status comes from the saved Xcode response metadata for `AID=-1`. HTTP 400 confirms rejection of that POST, but does not identify whether soft stickiness failed, requests arrived out of order, or another server-side condition caused it. OFF has no early POST. + +A fresh HTTP/2 connection was verified for each trial's first transport request, not inferred from creating a new service or process. In ON trials, the early POST could create the connection first and the handshake GET could reuse it. DNS, radio, and server state may remain warm. Repeated response-metadata callbacks for one request are counted once. + +Connection setup is `connectEndDate - connectStartDate` and includes the TLS handshake. TLS handshake is `secureConnectionEndDate - secureConnectionStartDate`, a portion of connection setup; do not add the two values. + +| Scenario | Pair | Setting | Test status | Early POST HTTP | Cold source | Handshake protocol | Handshake reused | Connection setup (incl. TLS, ms) | TLS handshake (ms) | Remote address | +|---|---:|:---:|---|:---:|---|---|:---:|---:|---:|---| +| omnient | 1 | OFF | completed | — | handshake | h2 | false | 27.000 | 17.000 | 2404:6800:400b:c015::451 | +| omnient | 1 | ON | completed | 200 | handshake | h2 | false | 84.000 | 14.000 | 2404:6800:400b:c015::451 | +| omnient | 2 | OFF | completed | — | handshake | h2 | false | 25.000 | 16.000 | 2404:6800:400b:c015::451 | +| omnient | 2 | ON | failed | 200 | handshake | h2 | false | 24.000 | 14.000 | 2404:6800:400b:c015::451 | +| omnient | 3 | OFF | completed | — | handshake | h2 | false | 25.000 | 15.000 | 2404:6800:400b:c015::451 | +| omnient | 3 | ON | completed | 200 | handshake | h2 | false | 19.000 | 12.000 | 2404:6800:400b:c015::451 | +| omnient | 4 | OFF | completed | — | handshake | h2 | false | 33.000 | 14.000 | 2404:6800:400b:c015::451 | +| omnient | 4 | ON | completed | 200 | handshake | h2 | false | 27.000 | 14.000 | 2404:6800:400b:c015::451 | +| omnient | 5 | OFF | completed | — | handshake | h2 | false | 27.000 | 17.000 | 2404:6800:400b:c015::451 | +| omnient | 5 | ON | completed | 200 | handshake | h2 | false | 34.000 | 23.000 | 2404:6800:400b:c015::451 | +| omnient | 6 | OFF | completed | — | handshake | h2 | false | 19.000 | 13.000 | 2404:6800:400b:c015::451 | +| omnient | 6 | ON | completed | 200 | handshake | h2 | false | 21.000 | 15.000 | 2404:6800:400b:c015::451 | +| omnient | 7 | OFF | completed | — | handshake | h2 | false | 28.000 | 18.000 | 2404:6800:400b:c015::451 | +| omnient | 7 | ON | completed | 200 | handshake | h2 | false | 55.000 | 13.000 | 2404:6800:400b:c015::451 | +| omnient | 8 | OFF | completed | — | handshake | h2 | false | 61.000 | 17.000 | 2404:6800:400b:c015::451 | +| omnient | 8 | ON | timeout | 400 | handshake | h2 | false | 62.000 | 17.000 | 2404:6800:400b:c015::451 | +| omnient | 9 | OFF | completed | — | handshake | h2 | false | 24.000 | 15.000 | 2404:6800:400b:c015::451 | +| omnient | 9 | ON | completed | 200 | handshake | h2 | false | 29.000 | 19.000 | 2404:6800:400b:c015::451 | +| omnient | 10 | OFF | completed | — | handshake | h2 | false | 27.000 | 17.000 | 2404:6800:400b:c015::451 | +| omnient | 10 | ON | completed | 200 | handshake | h2 | false | 32.000 | 18.000 | 2404:6800:400b:c015::451 | +| viewfinder | 1 | OFF | failed | — | handshake | h2 | false | 28.000 | 17.000 | 2404:6800:400b:c015::451 | +| viewfinder | 1 | ON | completed | 200 | handshake | h2 | false | 33.000 | 14.000 | 2404:6800:400b:c015::451 | +| viewfinder | 2 | OFF | completed | — | handshake | h2 | false | 24.000 | 12.000 | 2404:6800:400b:c015::451 | +| viewfinder | 2 | ON | completed | 200 | handshake | h2 | false | 26.000 | 15.000 | 2404:6800:400b:c015::451 | +| viewfinder | 3 | OFF | completed | — | handshake | h2 | false | 23.000 | 16.000 | 2404:6800:400b:c015::451 | +| viewfinder | 3 | ON | completed | 400 | handshake | h2 | false | 26.000 | 16.000 | 2404:6800:400b:c015::451 | +| viewfinder | 4 | OFF | failed | — | handshake | h2 | false | 28.000 | 15.000 | 2404:6800:400b:c015::451 | +| viewfinder | 4 | ON | completed | 400 | handshake | h2 | false | 57.000 | 16.000 | 2404:6800:400b:c015::451 | +| viewfinder | 5 | OFF | completed | — | handshake | h2 | false | 22.000 | 16.000 | 2404:6800:400b:c015::451 | +| viewfinder | 5 | ON | completed | 200 | handshake | h2 | false | 40.000 | 15.000 | 2404:6800:400b:c015::451 | +| viewfinder | 6 | OFF | completed | — | handshake | h2 | false | 21.000 | 12.000 | 2404:6800:400b:c015::451 | +| viewfinder | 6 | ON | completed | 200 | handshake | h2 | false | 51.000 | 13.000 | 2404:6800:400b:c015::451 | +| viewfinder | 7 | OFF | completed | — | handshake | h2 | false | 31.000 | 13.000 | 2404:6800:400b:c015::451 | +| viewfinder | 7 | ON | completed | 400 | handshake | h2 | false | 22.000 | 13.000 | 2404:6800:400b:c015::451 | +| viewfinder | 8 | OFF | completed | — | handshake | h2 | false | 55.000 | 17.000 | 2404:6800:400b:c015::451 | +| viewfinder | 8 | ON | failed | 400 | handshake | h2 | false | 303.000 | 293.000 | 2404:6800:400b:c015::451 | +| viewfinder | 9 | OFF | completed | — | handshake | h2 | false | 30.000 | 14.000 | 2404:6800:400b:c015::451 | +| viewfinder | 9 | ON | completed | 200 | handshake | h2 | false | 26.000 | 14.000 | 2404:6800:400b:c015::451 | +| viewfinder | 10 | OFF | completed | — | handshake | h2 | false | 25.000 | 14.000 | 2404:6800:400b:c015::451 | +| viewfinder | 10 | ON | completed | 400 | handshake | h2 | false | 24.000 | 13.000 | 2404:6800:400b:c015::451 | + +## M1 and M3 dispatch + +The handshake payload column is the request's encoded `count`. `count=0` means neither M1 nor M3 was in the handshake request itself. `early POST` means the first request containing that message was an `AID=-1` POST logged before WebChannel opened, concurrent with the handshake; it does not prove server arrival order or acceptance. `post-open POST` means its first request was logged after the channel opened. + +M1 is message offset 0. The demo sends M3 at offset 1 in Omnient and offset 2 in Viewfinder (after M2 Heartbeat). Request body prefixes expose `count` and `ofs`, which identify the first HTTP request containing each queued message. A rejected early POST may be retried after opening; the table records the first dispatch. + +The observed M1 delay is measured from the client connect timestamp to the M1 `send()` call; scheduling can vary slightly from the requested delay. + +| Scenario | Pair | Setting | M1 after connect (ms) | Handshake payload | M1 first request | M3 first request | +|---|---:|:---:|---:|:---:|---|---| +| omnient | 1 | OFF | 50.304 | count=0 | post-open POST | post-open POST | +| omnient | 1 | ON | 52.865 | count=0 | early POST | early POST | +| omnient | 2 | OFF | 52.478 | count=0 | post-open POST | post-open POST | +| omnient | 2 | ON | 51.285 | count=0 | early POST | early POST | +| omnient | 3 | OFF | 51.087 | count=0 | post-open POST | post-open POST | +| omnient | 3 | ON | 52.562 | count=0 | early POST | early POST | +| omnient | 4 | OFF | 51.808 | count=0 | post-open POST | post-open POST | +| omnient | 4 | ON | 50.489 | count=0 | early POST | early POST | +| omnient | 5 | OFF | 50.592 | count=0 | post-open POST | post-open POST | +| omnient | 5 | ON | 51.444 | count=0 | early POST | early POST | +| omnient | 6 | OFF | 50.449 | count=0 | post-open POST | post-open POST | +| omnient | 6 | ON | 51.799 | count=0 | early POST | early POST | +| omnient | 7 | OFF | 51.580 | count=0 | post-open POST | post-open POST | +| omnient | 7 | ON | 52.847 | count=0 | early POST | early POST | +| omnient | 8 | OFF | 52.240 | count=0 | post-open POST | post-open POST | +| omnient | 8 | ON | 52.907 | count=0 | early POST | early POST | +| omnient | 9 | OFF | 51.205 | count=0 | post-open POST | post-open POST | +| omnient | 9 | ON | 52.866 | count=0 | early POST | early POST | +| omnient | 10 | OFF | 52.473 | count=0 | post-open POST | post-open POST | +| omnient | 10 | ON | 50.740 | count=0 | early POST | early POST | +| viewfinder | 1 | OFF | 52.201 | count=0 | post-open POST | post-open POST | +| viewfinder | 1 | ON | 50.372 | count=0 | early POST | post-open POST | +| viewfinder | 2 | OFF | 51.271 | count=0 | post-open POST | post-open POST | +| viewfinder | 2 | ON | 50.958 | count=0 | early POST | post-open POST | +| viewfinder | 3 | OFF | 50.601 | count=0 | post-open POST | post-open POST | +| viewfinder | 3 | ON | 51.225 | count=0 | early POST | post-open POST | +| viewfinder | 4 | OFF | 51.768 | count=0 | post-open POST | post-open POST | +| viewfinder | 4 | ON | 52.828 | count=0 | early POST | post-open POST | +| viewfinder | 5 | OFF | 52.048 | count=0 | post-open POST | post-open POST | +| viewfinder | 5 | ON | 51.827 | count=0 | early POST | post-open POST | +| viewfinder | 6 | OFF | 51.553 | count=0 | post-open POST | post-open POST | +| viewfinder | 6 | ON | 52.863 | count=0 | early POST | post-open POST | +| viewfinder | 7 | OFF | 51.563 | count=0 | post-open POST | post-open POST | +| viewfinder | 7 | ON | 51.818 | count=0 | early POST | post-open POST | +| viewfinder | 8 | OFF | 50.862 | count=0 | post-open POST | post-open POST | +| viewfinder | 8 | ON | 50.518 | count=0 | early POST | post-open POST | +| viewfinder | 9 | OFF | 52.851 | count=0 | post-open POST | post-open POST | +| viewfinder | 9 | ON | 52.908 | count=0 | early POST | post-open POST | +| viewfinder | 10 | OFF | 51.151 | count=0 | post-open POST | post-open POST | +| viewfinder | 10 | ON | 50.377 | count=0 | early POST | post-open POST | + +## Observations and limits + +Omnient sends M3 during connection establishment; Viewfinder schedules M3 about 500 ms later, after the channel opened in every completed Viewfinder trial. Fresh connection verification is to the reached edge, not a cold DNS lookup or cold backend application state. + +The initial early POST returned HTTP 400 in 6/20 ON trials. Of those trials, 4 completed; inspect the logs to distinguish successful retries from incomplete runs. + +The Xcode logs contain retry diagnostics in ON trials for Omnient pairs 2, 8 and Viewfinder pairs 3, 4, 7, 8, 10. Those retries can affect TTFA and TTFD; the raw logs should be consulted before attributing a timing difference solely to the handshake option. + +Incomplete trials: omnient pair 2 ON; omnient pair 8 ON; viewfinder pair 1 OFF (Xcode log includes network connection lost, -1005); viewfinder pair 4 OFF; viewfinder pair 8 ON (Xcode log includes network connection lost, -1005). + diff --git a/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/report.md b/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/report.md new file mode 100644 index 0000000..307758d --- /dev/null +++ b/webchannel/benchmark/lens/2026-10-08_15-04_binary-cold-50ms_JST/report.md @@ -0,0 +1,55 @@ +# Lens benchmark — 2026-10-08 physical-device cold-connection run (binary encoding) + +## Experiment specification + +[Google net_http: Lens Latency Mimic & Shutter Benchmark Mode](https://github.com/google/net_http/blob/main/webchannel/objc/demo/WebChanneliOSDemo/DESIGN.md#d-lens-latency-mimic--shutter-benchmark-mode). + +## Environment + +| Field | Recorded value | +|---|---| +| Device | iPhone SE (3rd generation), hardware model `iPhone14,6` | +| iOS | 26.3.1, from XCTest | +| Network switches | Not independently recorded for this run | +| Endpoint | `https://webchannel.sandbox.google.com/staging/channel/lens` | +| Mac | macOS 26.5.1; Xcode 26.6; Build version 17F113 | +| Source | Git HEAD `aa71e660c4d409919bec313fccc9d1376baa103c` plus uncommitted benchmark instrumentation | +| Test period | 2026-10-08 15:06–15:11 local time, from artifact timestamps | +| Test execution | 10 alternating OFF/ON pairs per scenario; a separate `xcodebuild test-without-building` invocation for each trial | +| Test result | 35 completed trials; 40 passed fresh-transport verification | +| Transport requirement | First transport: `h2`, a new TCP/TLS connection on the handshake GET/POST or early POST; if the GET reused the early POST connection, matching address and local port | + +## Procedure and parameters + +1. Build the XCTest bundle once, then launch exactly one cold-trial test method per `xcodebuild test-without-building` invocation. Keep parallel testing disabled and retain each `.xcresult` bundle. +2. Run Omnient first, then Camera Viewfinder. Each pair runs `fastHandshake2=false` (OFF), then `fastHandshake2=true` (ON). The XCTest creates a new `WebChannelService` and WebChannel client per trial. +3. Use `imageSizeKb=150`, `detectionDelayMs=50`, `initialMessageDelayMs=50`, `enableBinaryEncoding=true`, `sendRawJson=true`, `fastHandshake=false`, `nonBlockingSend=false`, `blockingHandshake=false`, `forceLongPolling=false`, and `detectBufferingProxy=false`. The 150 KB value is metadata; no 150 KB image is uploaded. +4. Schedule M1 Sticky Cluster Info 50 ms after `connect()` returns. Omnient sends M3 Prefetch immediately after M1; Camera Viewfinder schedules M2 Heartbeat at +200 ms and M3 Prefetch at +500 ms after `connect()` returns. M4 Final Capture follows preliminary detections. Each trial has a 60-second completion deadline. +5. Record Handshake (`webChannelOpened` minus connect), TTFA (M3 send to stream ACK), TTFD (M3 send to preliminary detections), and M4 RTT (M4 send to interaction response). +6. Include a pair in the raw measurement tables only if both runs completed, both trials meet the transport requirement, and the absolute ON/OFF handshake-duration difference is ≤20 ms. Calculate that difference from full-precision values. Keep every trial in the raw attachments and audit. + +## Omnient: valid pair raw measurements + +Values shown in the table are rounded to three decimal places. + +| Run # | fastHandshake2 | Handshake (ms) | TTFA (ms) | TTFD (ms) | M4 RTT (ms) | +|---:|:---:|---:|---:|---:|---:| +| 3 | OFF | 183.940 | 274.629 | 321.384 | 135.920 | +| 3 | ON | 179.153 | 150.608 | 197.459 | 155.047 | +| 4 | OFF | 188.329 | 301.885 | 322.818 | 140.845 | +| 4 | ON | 193.633 | 517.116 | 540.622 | 145.079 | +| 6 | OFF | 166.148 | 267.794 | 317.084 | 149.240 | +| 6 | ON | 164.204 | 206.971 | 255.013 | 161.305 | + +## Camera Viewfinder: valid pair raw measurements + +Values shown in the table are rounded to three decimal places. + +| Run # | fastHandshake2 | Handshake (ms) | TTFA (ms) | TTFD (ms) | M4 RTT (ms) | +|---:|:---:|---:|---:|---:|---:| +| 2 | OFF | 173.476 | 155.322 | 209.601 | 169.366 | +| 2 | ON | 162.429 | 135.548 | 184.422 | 140.504 | +| 5 | OFF | 173.993 | 139.603 | 190.365 | 147.950 | +| 5 | ON | 191.875 | 145.243 | 195.553 | 139.722 | +| 9 | OFF | 165.460 | 137.316 | 187.138 | 143.419 | +| 9 | ON | 180.641 | 478.588 | 478.829 | 134.641 | diff --git a/webchannel/benchmark/lens/AGENTS.md b/webchannel/benchmark/lens/AGENTS.md index e8f8311..d067655 100644 --- a/webchannel/benchmark/lens/AGENTS.md +++ b/webchannel/benchmark/lens/AGENTS.md @@ -5,7 +5,7 @@ When changing or generating files under this directory, follow [README.md](READM - Write reports in English. Each run's `report.md` must link the specification and record the physical-device environment, network switch states when known, experiment procedure, parameter values, and separate Omnient and Camera Viewfinder raw measurement tables with `Run #` as the first column. - Run 10 OFF/ON pairs per scenario unless the user changes the count. State the inclusion rule: both runs completed and their full-precision handshake durations differ by at most 10 ms by default, or the run-specific threshold explicitly requested by the user. For cold-connection runs, also require verified fresh HTTP/2 transport for both trials. Apply any explicitly requested run-specific outlier omission without changing the raw files. - Do not put median or other summary statistics, comparisons, interpretation, an excluded-pair list, or artifact links in `report.md`. Keep the table values rounded to three decimals and preserve every original measurement in raw artifacts. -- Put per-trial transport evidence, early POST HTTP status, and available evidence of whether M1/M3 were in the handshake request, a concurrent early POST, or a later POST in `audit.md`. Keep analysis of transport behavior and limitations there, separate from `report.md`. +- Put per-trial transport evidence, early POST HTTP status, and available evidence of whether M1/M3 were in the handshake request, a concurrent early POST, or a later POST in `connection-reuse-audit.md`. Keep analysis of transport behavior and limitations there, separate from `report.md`. - Put descriptions and direct links to raw CSV, JSON, logs, and available result bundles in `artifacts.md`. A result bundle need not be checked in if its exported evidence is retained. - For new cold-connection runs, store per-trial Xcode and attachment-export logs in `logs/`, result bundles in `xcresults/`, and exported attachments in `attachments/`. Preserve earlier run layouts and keep the summarizer compatible with both. - Describe an early POST HTTP 400 as a rejection. Client logs alone do not establish whether soft stickiness failed or requests arrived out of order. diff --git a/webchannel/benchmark/lens/README.md b/webchannel/benchmark/lens/README.md index aa0323a..c0e07c2 100644 --- a/webchannel/benchmark/lens/README.md +++ b/webchannel/benchmark/lens/README.md @@ -8,18 +8,20 @@ For a cold-connection run, build the demo XCTest bundle once, run one cold-trial Set `LENS_BINARY_ENCODING=1` when invoking `run-cold-benchmark.sh` to run the dedicated binary-encoding cold trials. Leave it unset for the original text-encoding trials. The exported JSON records the setting, and the summarizer includes it in the report parameters. +Set `LENS_INITIAL_MESSAGE_DELAY_MS=N` to schedule Lens M1 `N` milliseconds after `connect()` returns, following the Generator benchmark's early-send timing. Omnient sends M3 immediately after M1; Viewfinder retains M2 at +200 ms and M3 at +500 ms after `connect()` returns. The runner passes this setting to the XCTest process through `TEST_RUNNER_`, and the JSON records both the requested delay and the observed time from the connect timestamp to M1 `send()`. The default is 0 ms. + For new runs, the runner stores each trial's Xcode log and attachment-export log under `OUTPUT_DIR/logs/`, result bundles under `OUTPUT_DIR/xcresults/`, and exported attachments under `OUTPUT_DIR/attachments/`. The 2026-10-08 13:40 JST rerun uses this layout after migration. Earlier runs retain their original layout; the summarizer reads both layouts. -Each run directory has `report.md` and `artifacts.md`. Cold runs with recorded transport evidence also have `audit.md`: +Each run directory has `report.md` and `artifacts.md`. New cold runs and the two most recent runs with recorded transport evidence have `connection-reuse-audit.md`; older runs retain `audit.md`: | File | Contents | |---|---| | `report.md` | Specification link, environment, procedure and parameters, and filtered raw measurement tables. No aggregate statistics, comparison, interpretation, excluded-pair list, or artifact links. | -| `audit.md` | When transport evidence is available: every trial's handshake transport record, initial early POST HTTP status, and transport-specific observations and limits. | +| `connection-reuse-audit.md` | When transport evidence is available: every trial's handshake transport record, initial early POST HTTP status, and transport-specific observations and limits. | | `artifacts.md` | Descriptions and direct links to raw CSV, JSON, logs, and available `.xcresult` bundles. | The raw attachments and, where applicable, the audit retain every trial. HTTP 400 on an early POST confirms rejection; client logs alone cannot assign the rejection to soft stickiness, request arrival order, or another server-side condition. A new HTTP/2 TCP/TLS connection to the reached edge does not imply cold DNS, radio, or backend state. Retaining a full `.xcresult` bundle is useful for later Xcode inspection but is not required for the report once its raw attachments and test evidence have been exported. Instructions for agents editing the runner, summarizer, or reports are in [AGENTS.md](AGENTS.md). -Recorded runs: [single-invocation run at 00:37 JST](2026-10-07_00-37-42_JST/report.md), [text-encoding cold-connection run at 15:21 JST](2026-10-07_15-21-10_JST/report.md), [binary-encoding cold-connection run at 17:27 JST](2026-10-07_17-27-44_binary-cold_JST/report.md), [binary-encoding rerun on 2026-10-08](2026-10-08_13-08_binary-cold-rerun_JST/report.md), [binary-encoding run with a 20 ms handshake threshold](2026-10-08_13-21_binary-cold-20ms_JST/report.md), and [its separate rerun at 13:40 JST](2026-10-08_13-39_binary-cold-20ms-rerun_JST/report.md). +Recorded runs: [single-invocation run at 00:37 JST](2026-10-07_00-37-42_JST/report.md), [text-encoding cold-connection run at 15:21 JST](2026-10-07_15-21-10_JST/report.md), [binary-encoding cold-connection run at 17:27 JST](2026-10-07_17-27-44_binary-cold_JST/report.md), [binary-encoding rerun on 2026-10-08](2026-10-08_13-08_binary-cold-rerun_JST/report.md), [binary-encoding run with a 20 ms handshake threshold](2026-10-08_13-21_binary-cold-20ms_JST/report.md), [its separate rerun at 13:40 JST](2026-10-08_13-39_binary-cold-20ms-rerun_JST/report.md), and [the 50 ms initial-message-delay run](2026-10-08_15-04_binary-cold-50ms_JST/report.md). diff --git a/webchannel/benchmark/lens/run-cold-benchmark.sh b/webchannel/benchmark/lens/run-cold-benchmark.sh index dd7e70d..9067feb 100644 --- a/webchannel/benchmark/lens/run-cold-benchmark.sh +++ b/webchannel/benchmark/lens/run-cold-benchmark.sh @@ -12,6 +12,10 @@ pairs=${3:-10} demo_dir=$(cd "$(dirname "$0")/../../objc/demo/WebChanneliOSDemo" && pwd) derived_data=${LENS_DERIVED_DATA:-/tmp/net-http-cold-build} binary_encoding=${LENS_BINARY_ENCODING:-0} +initial_message_delay_ms=${LENS_INITIAL_MESSAGE_DELAY_MS:-0} +case "$initial_message_delay_ms" in + ''|*[!0-9]*) echo "LENS_INITIAL_MESSAGE_DELAY_MS must be a nonnegative integer" >&2; exit 2 ;; +esac case "$binary_encoding" in 0) test_prefix=testCold ;; 1) test_prefix=testColdBinary ;; @@ -35,7 +39,7 @@ for scenario in Omnient Viewfinder; do log="$output_dir/logs/$trial.log" export_dir="$output_dir/attachments/$trial-attachments" echo "Running $trial" - if xcodebuild test-without-building \ + if TEST_RUNNER_LENS_INITIAL_MESSAGE_DELAY_MS="$initial_message_delay_ms" xcodebuild test-without-building \ -workspace "$demo_dir/WebChanneliOSDemo.xcworkspace" \ -scheme WebChanneliOSDemo -configuration Debug \ -destination "id=$device_id" -derivedDataPath "$derived_data" \ diff --git a/webchannel/benchmark/lens/summarize-cold-benchmark.py b/webchannel/benchmark/lens/summarize-cold-benchmark.py index 59f4f7d..051d88d 100644 --- a/webchannel/benchmark/lens/summarize-cold-benchmark.py +++ b/webchannel/benchmark/lens/summarize-cold-benchmark.py @@ -139,9 +139,13 @@ def main(): first = next((row for row in trials.values() if row), {}) binary_encoding = first.get("enableBinaryEncoding", False) + initial_message_delay_ms = first.get("initialMessageDelayMs", 0) if any(row is not None and row.get("enableBinaryEncoding", False) != binary_encoding for row in trials.values()): raise ValueError("Run contains mixed binary-encoding settings") + if any(row is not None and row.get("initialMessageDelayMs", 0) != initial_message_delay_ms + for row in trials.values()): + raise ValueError("Run contains mixed initial-message delay settings") logs = [trial_log(root, *key) for key in trials] logs = [path for path in logs if path.exists()] if logs: @@ -164,6 +168,7 @@ def main(): if args.handshake_threshold_ms is not None: metadata["handshakeThresholdMs"] = args.handshake_threshold_ms metadata.setdefault("handshakeThresholdMs", 10) + metadata.setdefault("initialMessageDelayMs", initial_message_delay_ms) threshold_ms = float(metadata["handshakeThresholdMs"]) if not math.isfinite(threshold_ms) or threshold_ms < 0: parser.error("handshake threshold must be a finite nonnegative number") @@ -207,8 +212,8 @@ def main(): "", "1. Build the XCTest bundle once, then launch exactly one cold-trial test method per `xcodebuild test-without-building` invocation. Keep parallel testing disabled and retain each `.xcresult` bundle.", "2. Run Omnient first, then Camera Viewfinder. Each pair runs `fastHandshake2=false` (OFF), then `fastHandshake2=true` (ON). The XCTest creates a new `WebChannelService` and WebChannel client per trial.", - f"3. Use `imageSizeKb=150`, `detectionDelayMs=50`, `enableBinaryEncoding={'true' if binary_encoding else 'false'}`, `sendRawJson=true`, `fastHandshake=false`, `nonBlockingSend=false`, `blockingHandshake=false`, `forceLongPolling=false`, and `detectBufferingProxy=false`. The 150 KB value is metadata; no 150 KB image is uploaded.", - "4. Omnient sends M1 Sticky Cluster Info and M3 Prefetch during connection establishment. Camera Viewfinder sends M1 at connection start, schedules M2 Heartbeat at +200 ms, and schedules M3 Prefetch at +500 ms. M4 Final Capture follows preliminary detections. Each trial has a 60-second completion deadline.", + f"3. Use `imageSizeKb=150`, `detectionDelayMs=50`, `initialMessageDelayMs={initial_message_delay_ms}`, `enableBinaryEncoding={'true' if binary_encoding else 'false'}`, `sendRawJson=true`, `fastHandshake=false`, `nonBlockingSend=false`, `blockingHandshake=false`, `forceLongPolling=false`, and `detectBufferingProxy=false`. The 150 KB value is metadata; no 150 KB image is uploaded.", + f"4. Schedule M1 Sticky Cluster Info {initial_message_delay_ms} ms after `connect()` returns. Omnient sends M3 Prefetch immediately after M1; Camera Viewfinder schedules M2 Heartbeat at +200 ms and M3 Prefetch at +500 ms after `connect()` returns. M4 Final Capture follows preliminary detections. Each trial has a 60-second completion deadline.", "5. Record Handshake (`webChannelOpened` minus connect), TTFA (M3 send to stream ACK), TTFD (M3 send to preliminary detections), and M4 RTT (M4 send to interaction response).", f"6. Include a pair in the raw measurement tables only if both runs completed, both trials meet the transport requirement, and the absolute ON/OFF handshake-duration difference is ≤{threshold_ms:g} ms. Calculate that difference from full-precision values. Keep every trial in the raw attachments and audit.", "", @@ -280,12 +285,14 @@ def main(): audit_lines.extend(["", "## M1 and M3 dispatch", "", "The handshake payload column is the request's encoded `count`. `count=0` means neither M1 nor M3 was in the handshake request itself. `early POST` means the first request containing that message was an `AID=-1` POST logged before WebChannel opened, concurrent with the handshake; it does not prove server arrival order or acceptance. `post-open POST` means its first request was logged after the channel opened.", "", "M1 is message offset 0. The demo sends M3 at offset 1 in Omnient and offset 2 in Viewfinder (after M2 Heartbeat). Request body prefixes expose `count` and `ofs`, which identify the first HTTP request containing each queued message. A rejected early POST may be retried after opening; the table records the first dispatch.", "", - "| Scenario | Pair | Setting | Handshake payload | M1 first request | M3 first request |", - "|---|---:|:---:|:---:|---|---|", + "The observed M1 delay is measured from the client connect timestamp to the M1 `send()` call; scheduling can vary slightly from the requested delay.", "", + "| Scenario | Pair | Setting | M1 after connect (ms) | Handshake payload | M1 first request | M3 first request |", + "|---|---:|:---:|---:|:---:|---|---|", ]) for (scenario, pair, setting), row in trials.items(): payload, m1, m3 = message_dispatch(root, scenario, pair, setting, handshake_transport(row)) - audit_lines.append(f"| {scenario} | {pair} | {setting.upper()} | {payload} | {m1} | {m3} |") + m1_delay = fmt(row["m1DelayFromConnectMs"]) if row and row.get("m1DelayFromConnectMs") is not None else "—" + audit_lines.append(f"| {scenario} | {pair} | {setting.upper()} | {m1_delay} | {payload} | {m1} | {m3} |") viewfinder_open_before_prefetch = all( row is not None and row.get("handshakeMs", float("inf")) < 500 for (scenario, _, _), row in trials.items() if scenario == "viewfinder" @@ -320,11 +327,11 @@ def main(): if failed_trials: audit_lines.extend([f"Incomplete trials: {'; '.join(failed_trials)}.", ""]) (root / "report.md").write_text("\n".join(lines)) - (root / "audit.md").write_text("\n".join(audit_lines) + "\n") + (root / "connection-reuse-audit.md").write_text("\n".join(audit_lines) + "\n") artifact_lines = [ f"# Lens benchmark artifacts — {metadata['runDate']} physical-device cold-connection run", "", - "[Report](report.md) · [Transport audit](audit.md) · [Run metadata](run-metadata.json)", + "[Report](report.md) · [Transport audit](connection-reuse-audit.md) · [Run metadata](run-metadata.json)", "", "Each trial has an Xcode log and exported attachments. Current runs keep logs in `logs/`, result bundles in `xcresults/`, and exported attachments in `attachments/`; older runs may keep these at the run root. The exported JSON and CSV preserve every attempted trial, including pairs omitted from the report tables. CSV values retain their recorded precision.", "", diff --git a/webchannel/objc/demo/WebChanneliOSDemo/README.md b/webchannel/objc/demo/WebChanneliOSDemo/README.md index 973a52c..9d65403 100644 --- a/webchannel/objc/demo/WebChanneliOSDemo/README.md +++ b/webchannel/objc/demo/WebChanneliOSDemo/README.md @@ -137,7 +137,7 @@ python3 webchannel/benchmark/lens/summarize-cold-benchmark.py OUTPUT_DIR 10 The runner starts one cold-trial test method per invocation of `xcodebuild test-without-building`. It alternates OFF/ON trials for Omnient and Viewfinder, retains each `.xcresult` under `OUTPUT_DIR/xcresults/` and exported -JSON/CSV under `OUTPUT_DIR/attachments/`, and writes `report.md`, `audit.md`, +JSON/CSV under `OUTPUT_DIR/attachments/`, and writes `report.md`, `connection-reuse-audit.md`, and `artifacts.md` in the output directory. The [Lens benchmark report guide](../../../benchmark/lens/README.md) describes the document layout. Per-trial Xcode and attachment-export logs are placed in @@ -149,6 +149,10 @@ address and local port. App-process restart alone is not used as evidence of a fresh connection; DNS, radio, and server state can remain warm. Set `LENS_BINARY_ENCODING=1` for a run with `enableBinaryEncoding=true`; the default remains `false`. +Set `LENS_INITIAL_MESSAGE_DELAY_MS=50` to schedule Lens M1 50 ms after +`connect()` returns, as in the Generator early-send experiment. Omnient M3 +follows M1 immediately; Viewfinder M2 and M3 remain scheduled at +200 ms and ++500 ms after `connect()` returns. --- diff --git a/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemo/WebChannelService.swift b/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemo/WebChannelService.swift index 5c0b5d8..b00e29b 100644 --- a/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemo/WebChannelService.swift +++ b/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemo/WebChannelService.swift @@ -18,6 +18,7 @@ struct LogEntry: Identifiable, Equatable { /// Core metrics captured during a Lens simulation run. struct LensBenchmarkMetrics: Equatable { var handshakeDurationMs: Double? = nil + var m1DelayFromConnectMs: Double? = nil var m3RttToAckMs: Double? = nil // Time to First ACK (TTFA) var m3TimeToFirstDetectionMs: Double? = nil // Time to First Detection (TTFD) var m4RttMs: Double? = nil // M4 Final Capture RTT @@ -340,15 +341,17 @@ final class WebChannelService: NSObject, @unchecked Sendable { /// Runs the Lens lifecycle latency benchmark. /// - Parameters: /// - endpointUrl: The WebChannel endpoint URL (e.g. /staging/channel/lens). - /// - isOmnient: If true, dispatches M1 (Sticky Cluster) and M3 (Prefetch) at T=0 - /// concurrently with handshake (0-RTT test). + /// - isOmnient: If true, dispatches M1 (Sticky Cluster) and M3 (Prefetch) + /// together during connection establishment. /// - imageSizeKb: Size of the dummy image payload for Prefetch (default 150KB). /// - detectionDelayMs: Backend detection inference delay to simulate (default 50ms). + /// - initialMessageDelayMs: Delay after connect() before M1 (and Omnient M3). func startLensBenchmark( endpointUrl: String, isOmnient: Bool = true, imageSizeKb: Int = 150, - detectionDelayMs: Int = 50 + detectionDelayMs: Int = 50, + initialMessageDelayMs: Int = 0 ) { disconnect() clearLogs() @@ -361,16 +364,50 @@ final class WebChannelService: NSObject, @unchecked Sendable { let optionsLog = "⚙️ Options: fastHandshake2=\(fastHandshake2), fastHandshake=\(fastHandshake), " + "nonBlockingSend=\(nonBlockingSend), binary=\(enableBinaryEncoding), " - + "imageSize=\(imageSizeKb)KB" + + "imageSize=\(imageSizeKb)KB, initialMessageDelayMs=\(initialMessageDelayMs)" log(optionsLog) log("==================================================================") connect(to: endpointUrl, clearLogHistory: false) + let sendInitialMessages: () -> Void = { [weak self] in + guard let self = self, self.lensMetrics.isRunning else { return } + self.sendLensStickyClusterInfo() + if isOmnient { + self.sendLensPrefetch(imageSizeKb: imageSizeKb, detectionDelayMs: detectionDelayMs) + } + } + let delayMs = max(0, initialMessageDelayMs) + if delayMs == 0 { + sendInitialMessages() + } else { + log("⏱ [Lens] Scheduled M1\(isOmnient ? " and M3" : "") for T+\(delayMs)ms...") + DispatchQueue.main.asyncAfter(deadline: .now() + Double(delayMs) / 1000.0) { + sendInitialMessages() + } + } + + if !isOmnient { + // Viewfinder M2 and M3 remain at T+200ms and T+500ms after connect(). + log("⏱ [Viewfinder] Warming channel with M2 Heartbeat, prefetch in 500ms...") + DispatchQueue.main.asyncAfter(deadline: .now() + 0.2) { [weak self] in + guard let self = self, self.lensMetrics.isRunning else { return } + self.sendLensHeartbeat() + } + DispatchQueue.main.asyncAfter(deadline: .now() + 0.5) { [weak self] in + guard let self = self, self.lensMetrics.isRunning else { return } + self.sendLensPrefetch(imageSizeKb: imageSizeKb, detectionDelayMs: detectionDelayMs) + } + } + } + + private func sendLensStickyClusterInfo() { let nowMs = Int64(Date().timeIntervalSince1970 * 1000) lensM1SendTimeMs = nowMs + let elapsed = (CFAbsoluteTimeGetCurrent() - connectTime) * 1000.0 + lensMetrics.m1DelayFromConnectMs = elapsed + log(String(format: "⏱ [Lens M1] send() at T+%.1fms from connect start", elapsed)) - // Message 1: Sticky Cluster Info let m1Payload: [String: Any] = [ "type": "sticky_cluster_info", "client_send_time_ms": nowMs, @@ -386,22 +423,6 @@ final class WebChannelService: NSObject, @unchecked Sendable { } else { sendPayload(m1Payload, description: "M1 StickyClusterInfo") } - - if isOmnient { - // Omnient mode: Send Prefetch immediately at T=0 - sendLensPrefetch(imageSizeKb: imageSizeKb, detectionDelayMs: detectionDelayMs) - } else { - // Camera Viewfinder mode: Send M2 heartbeat during warmup, then Prefetch at 500ms - log("⏱ [Viewfinder] Warming channel with M2 Heartbeat, prefetch in 500ms...") - DispatchQueue.main.asyncAfter(deadline: .now() + 0.2) { [weak self] in - guard let self = self, self.lensMetrics.isRunning else { return } - self.sendLensHeartbeat() - } - DispatchQueue.main.asyncAfter(deadline: .now() + 0.5) { [weak self] in - guard let self = self, self.lensMetrics.isRunning else { return } - self.sendLensPrefetch(imageSizeKb: imageSizeKb, detectionDelayMs: detectionDelayMs) - } - } } private func sendLensHeartbeat() { diff --git a/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemoTests/LensBenchmarkTests.swift b/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemoTests/LensBenchmarkTests.swift index 1b7c75c..96fad58 100644 --- a/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemoTests/LensBenchmarkTests.swift +++ b/webchannel/objc/demo/WebChanneliOSDemo/WebChanneliOSDemoTests/LensBenchmarkTests.swift @@ -33,6 +33,12 @@ final class LensBenchmarkTests: XCTestCase { ? min(max(Int(environment["LENS_BENCHMARK_REPETITIONS"] ?? "10") ?? 10, 1), 50) : 1 let settings = coldSetting.map { [$0] } ?? [false, true] let endpoint = environment["LENS_BENCHMARK_ENDPOINT"] ?? defaultEndpoint + guard let initialMessageDelayMs = Int(environment["LENS_INITIAL_MESSAGE_DELAY_MS"] ?? "0"), + initialMessageDelayMs >= 0 + else { + XCTFail("LENS_INITIAL_MESSAGE_DELAY_MS must be a nonnegative integer") + return + } var rows: [[String: Any]] = [] var failures: [String] = [] @@ -46,7 +52,8 @@ final class LensBenchmarkTests: XCTestCase { endpointUrl: endpoint, isOmnient: isOmnient, imageSizeKb: 150, - detectionDelayMs: 50 + detectionDelayMs: 50, + initialMessageDelayMs: initialMessageDelayMs ) } @@ -77,11 +84,13 @@ final class LensBenchmarkTests: XCTestCase { "endpoint": endpoint, "imageSizeKb": 150, "detectionDelayMs": 50, + "initialMessageDelayMs": initialMessageDelayMs, "deviceModel": UIDevice.current.model, "systemVersion": UIDevice.current.systemVersion, "log": service.combinedLogsText, ] if let value = metrics.handshakeDurationMs { result["handshakeMs"] = value } + if let value = metrics.m1DelayFromConnectMs { result["m1DelayFromConnectMs"] = value } if let value = metrics.m3RttToAckMs { result["ttfaMs"] = value } if let value = metrics.m3TimeToFirstDetectionMs { result["ttfdMs"] = value } if let value = metrics.m4RttMs { result["m4RttMs"] = value } @@ -142,7 +151,7 @@ final class LensBenchmarkTests: XCTestCase { jsonAttachment.lifetime = .keepAlways add(jsonAttachment) - let columns = ["scenario", "repetition", "fastHandshake2", "status", "coldConnection", "handshakeMs", "ttfaMs", "ttfdMs", "m4RttMs"] + let columns = ["scenario", "repetition", "fastHandshake2", "initialMessageDelayMs", "m1DelayFromConnectMs", "status", "coldConnection", "handshakeMs", "ttfaMs", "ttfdMs", "m4RttMs"] let csv = ([columns.joined(separator: ",")] + rows.map { row in columns.map { key in String(describing: row[key] ?? "") }.joined(separator: ",") }).joined(separator: "\n") + "\n"