diff --git a/AK/Debug.h.in b/AK/Debug.h.in index a734278ca4..745963d620 100644 --- a/AK/Debug.h.in +++ b/AK/Debug.h.in @@ -238,6 +238,10 @@ # cmakedefine01 REQUESTSERVER_DEBUG #endif +#ifndef REQUESTSERVER_WIRE_DEBUG +# cmakedefine01 REQUESTSERVER_WIRE_DEBUG +#endif + #ifndef RESOURCE_DEBUG # cmakedefine01 RESOURCE_DEBUG #endif diff --git a/Documentation/RequestServerWireLogging.md b/Documentation/RequestServerWireLogging.md new file mode 100644 index 0000000000..821d4a2523 --- /dev/null +++ b/Documentation/RequestServerWireLogging.md @@ -0,0 +1,409 @@ +# RequestServer wire-activity logging + +RequestServer emits up to four `dbgln` lines per HTTP fetch that actually +hit the network, so you can correlate "dead air" in a profile with the +download (or stall) responsible for it. + +Cache hits do **not** appear here — only requests that produced traffic. +That is the point: if the log is silent during a profile gap, the gap is +not a download. + +## The lines + +For every fetched request you get a `wire:` line. Successful fetches that +delivered any body also get `wire+:` (decoded view), `wire++:` (encoded +view, when curl provided wire-level progress), and `wire^:` (pre-network +time spent inside RequestServer plus drain delay). When more than one +request completes in the same curl multi tick, a single `wire-batch:` +line is emitted explaining why their `wire:` timestamps cluster. + +Several diagnostic lines fire only when something interesting happened +and don't belong to any single request: `wire-stall:` flags +event-loop blocks and slow synchronous curl calls, `wire-burst:` flags +request floods from a client, `wire-pipe-pressure:` flags WebContent +back-pressure on the response pipe, `LibDNS wire-dns:` flags slow DNS +lookups (especially the blocking `getaddrinfo` fall-back), and `UI +wire-cookie:` flags slow cookie-jar lookups on the UI side. See the +"Process-wide diagnostic lines" section below. + +### `wire:` — one-line summary + +``` +wire: KIND METHOD URL HTTP-VERSION -> STATUS + | wire X.X KiB sent X.X KiB + | total N ms = queue N + dns N + tcp N + tls N + req N + wait N + body N + | wire X.X KiB/s avg, X.X KiB/s during body +``` + +Fields: + +- **KIND** — what happened: + - `DOWNLOAD` — full body fetched from origin. + - `REVAL-304` — conditional GET hit the cache; server returned 304, we + served the cached body. + - `REVAL-FULL` — conditional GET that the server invalidated (returned + new content), so we replaced the cache entry. + - `FAIL` — curl failed before completion. The line collapses to + `... -> error: (after N ms, wire X.X KiB)`. + - `[bg]` suffix on the kind marks a background revalidation triggered + by `stale-while-revalidate`. +- **wire X.X KiB** — bytes received **on the wire** (encoded; gzip / + brotli / etc. as transferred). Comes from `CURLINFO_SIZE_DOWNLOAD_T`. + Read this carefully — see the wire-vs-decoded section below. +- **sent X.X KiB** — request body bytes uploaded. +- **total N ms** — request lifetime, broken into libcurl phases. All + phase numbers are wall-time deltas: + - `queue` — time waiting in libcurl's pre-start queue (HTTP/2 and + HTTP/3 stream multiplexing usually puts you here briefly). + - `dns` — name resolution. + - `tcp` — TCP handshake (or QUIC connect on HTTP/3). + - `tls` — TLS handshake. Zero on plaintext, and zero on a reused + connection — see "Reused-connection timing" below. + - `req` — time between handshake completing and being ready to send + the request bytes. + - `wait` — server processing / time-to-first-byte. A high `wait` with + everything else low means the origin took its time before sending + the first response byte. + - `body` — time from first response byte to last response byte. +- **wire X.X KiB/s avg** — `CURLINFO_SPEED_DOWNLOAD_T`, averaged over + the entire request including TTFB. Useful as a sanity check, not as a + throughput number. +- **wire X.X KiB/s during body** — wire bytes divided by `body` time. + This is the throughput you actually got while bytes were flowing. + +### `wire+:` — decoded-side per-chunk stats + +``` +wire+: decoded chunks=N bytes=X.X KiB span=N ms thru=X.X KiB/s + | gap avg=N ms max=N ms stalls(>100ms)=N + | worst gap began at +N ms after X.X KiB decoded + | chunk bytes avg=N min=N max=N +``` + +Sampled inside our `WRITEFUNCTION` callback, so all numbers here are +**post-decompression** — i.e. the bytes our consumer actually receives. + +- **chunks=N** — number of times curl handed us a buffer of decoded + bytes. +- **bytes=X.X KiB** — total decoded body size (sum of all chunks). +- **span=N ms** — wall time between the first decoded chunk and the + last. +- **thru=X.X KiB/s** — `bytes / span`, throughput as the consumer + experienced it. +- **gap avg / max** — inter-chunk spacing. `max` is the longest pause + between two consecutive decoded chunks. +- **stalls(>100ms)=N** — count of inter-chunk gaps longer than 100 ms. + Useful for "was this one big pause, or several smaller ones?". +- **worst gap began at +N ms after X.X KiB decoded** — locates the + worst gap in the timeline. If the answer is `+5 ms after 0.0 KiB`, + the server flushed once and then thought; if it is + `+800 ms after 90% of bytes`, the tail dragged. +- **chunk bytes avg / min / max** — distribution of decoded chunk + sizes. + +### `wire++:` — wire-side per-progress-tick stats + +``` +wire++: wire bytes=X.X KiB span=N ms thru=X.X KiB/s + | wire max gap=N ms stalls(>100ms)=N + | worst wire gap began at +N ms after X.X KiB on the wire + | compression=Yx +``` + +Sampled inside `CURLOPT_XFERINFOFUNCTION`, which curl invokes both as +bytes hit the socket and as a heartbeat during silence. All numbers +here are **wire bytes** (encoded, before decompression). + +- **wire bytes / span / thru** — encoded-side equivalents of the + decoded line. `thru` is the real network throughput while bytes were + flowing. +- **wire max gap / stalls / worst gap began at** — same idea as the + decoded line, but reflecting actual silence on the network. This is + what you want when the question is "is the server pausing or is curl + buffering?". +- **compression=Yx** — `decoded_bytes / wire_bytes`. Common HTML pages + land at 5–10×; static assets that are already compressed (.jpg, + .mp3, .woff2) land at 1×. + +### `wire^:` — pre-network time spent inside RequestServer + +``` +wire^: internal pre-curl=N ms = cache+init N + our-dns N + cookie N + curl-setup N | drain delay N ms +``` + +Wall-time accounting for everything that happens **before** libcurl owns the +request, plus the gap between curl marking it done and us logging. + +- **internal pre-curl** — `curl_added_at - created_at`. Total time this + request spent inside our state machine before `curl_multi_add_handle`. + When this is a meaningful fraction of `total` on the `wire:` line, the + delay is ours, not the network's. +- **cache+init** — Init / ReadCache / WaitForCache time. Big numbers + here mean cache contention or a slow disk-cache lookup. +- **our-dns** — time inside our DNS resolver. Distinct from libcurl's + `dns` field on the `wire:` line, which is **0** because we + pre-resolve and pass the address via `CURLOPT_RESOLVE`. If the + `wire:` line says `dns 0` and you trust the network is fine but + things still feel slow, look here. +- **cookie** — round-trip IPC to the UI process to retrieve cookies for + the URL. Skipped (`-`) for credential-less requests. +- **curl-setup** — gap from the last completed pre-network step to + `curl_multi_add_handle`. Should be very small; if it isn't, something + in `handle_fetch_state` got expensive. +- **drain delay** — `complete_observed_at - last_wire_byte_at`. How + long between the last byte landing and `check_active_requests` + noticing the completion. Usually sub-ms — non-zero means an event-loop + delay between curl seeing the end and us draining its message queue. + +Fields can show `-` when the relevant phase didn't run (e.g. +`our-dns -` for connect-only requests, `cookie -` when credentials +were disabled). + +### `wire-batch:` — multiple completions per drain pass + +``` +RequestServer wire-batch: drained N completions in one curl multi tick +``` + +Emitted once per `check_active_requests` call when more than one request +completed since the previous drain. When you see this followed by N +`wire:` lines all sharing the same timestamp prefix, the clustering is +**cosmetic**: we drained the curl multi handle's done-queue in a tight +loop, so the `dbgln` calls happen microseconds apart. The actual +network completion times can be reconstructed from the `total` / +`body` numbers on each request, walked back from the drain timestamp. + +If you want true per-request completion times, take the drain +timestamp and subtract each request's `drain delay` from `wire^:`. + +## Process-wide diagnostic lines + +These do **not** belong to any one request. They surface conditions that +affect the whole RequestServer process or its peers (WebContent, the UI +process). When investigating a stall, look at these first — a single +`wire-stall:` line often explains a dozen confusing `wire:` lines that +follow. + +### `wire-stall:` — event-loop block detector + +``` +RequestServer wire-stall: N ms event-loop gap before 'LABEL' (previous handler: 'PREV') +RequestServer wire-stall: curl call 'LABEL' took N ms (synchronous in event loop) +``` + +Two flavours: + +- **Event-loop gap.** Every notifier/handler we control samples + `MonotonicTime::now()` on entry. If more than 100 ms passed since the + previous sample, this fires, naming both the handler that just woke up + and the previous handler that was the last thing to run. If `PREV` is + the same handler each time, that handler is doing too much work + synchronously. If `LABEL` is `curl-socket-ready` the kernel has been + trying to deliver bytes to us for that long. + + **Exception:** when `LABEL` is `curl-timer-fired` and the timer fired + within ±50 ms of the time libcurl asked us to wake it, the gap is + by design (libcurl's internal heartbeat — typically 250 ms intervals) + and the log line is suppressed. A real stall — the timer fires much + later than its scheduled time — still reports. +- **Synchronous curl call.** `curl_multi_socket_action` should be very + fast — it just hands a socket event to libcurl. If a single call + exceeds 50 ms, libcurl is doing real work synchronously (TLS handshake + on a fresh connection, certificate validation, callback dispatch into + our `WRITEFUNCTION`). That work blocks every other request. + +Labels currently emitted: `curl-timer-fired`, `curl-socket-ready`, +`check-active-requests`, `ipc-start-request`, `ipc-start-revalidation`, +`ipc-retrieved-cookie`, plus the curl wrappers +`multi_socket_action(timeout)` and `multi_socket_action(socket)`. + +### `wire-burst:` — request flood from a client + +``` +RequestServer wire-burst: client N sent M requests in <100 ms +``` + +Per-client `start_request` arrival counter. When a single client lands +more than 5 `start_request` IPCs in a 100 ms window, the count is logged +the first time the next request arrives outside that window. Useful for +correlating a `wire-stall:` with "this is the burst that hit us". + +### `wire-pipe-pressure:` — WebContent back-pressure on the response pipe + +``` +RequestServer wire-pipe-pressure: GET URL pipe full, buffering=N bytes +RequestServer wire-pipe-pressure: GET URL unblocked after N ms (peak buffered=N bytes); WebContent likely behind +``` + +Fires when `m_client_request_pipe->write` returns `EAGAIN` / +`EWOULDBLOCK`. RequestServer is producing response bytes faster than +WebContent's main thread can drain them — almost always because +WebContent is busy parsing HTML, executing JavaScript, or doing layout. +The "unblocked" line fires when the pipe drains and we resume writing, +but only if the back-pressure window lasted more than 50 ms. The +per-request totals are also surfaced in the `wire^:` line as +`pipe back-pressure events=N total=N ms peak-buffered=N bytes`. This is +the "WebContent is behind" diagnosis — it doesn't mean RequestServer is +slow. + +### `LibDNS wire-dns:` — DNS lookup synchronous portion (and worker completions) + +``` +LibDNS wire-dns: lookup(NAME) path=PATH sync=N ms +LibDNS wire-dns: lookup(NAME) path=system-resolver-bg total=N ms = A(queue N + work N) | AAAA(queue N + work N) (off event loop) +``` + +The first form is emitted by `DNS::Resolver::lookup` whenever its +**synchronous** portion takes more than 5 ms. The synchronous portion is +what holds the event loop — anything past trivial here is interesting. +`path` classifies how the lookup was satisfied: + +- `cache-hit` — answered entirely from our in-memory cache. +- `literal-ipv4` / `literal-ipv6` — `name` was an IP address literal. +- `system-resolver-bg` — dispatched two parallel `getaddrinfo` calls + to ThreadPool workers, one for `AF_INET` (A records) and one for + `AF_INET6` (AAAA records). The split avoids buggy stub resolvers + (notably systemd-resolved under load) that drop the AAAA half of a + coupled query and stall both. The promise resolves as soon as one + side returns records, with a 50 ms grace window for the other side + (Happy Eyeballs v2's "Resolution Delay", RFC 8305) so curl can prefer + IPv6 when both are available. + + The synchronous portion is just the dispatch (sub-ms). When both + workers have completed, a single line fires from the originating + event loop with both halves of the breakdown: + - `A(queue N + work N)` — IPv4 worker timing. + - `queue` — wall time waiting in the ThreadPool work queue. + - `work` — wall time inside `getaddrinfo` for AF_INET. + - `AAAA(queue N + work N)` — same for the IPv6 worker. + - `total` — wall-clock from dispatch to both workers reporting + completion. May be much longer than what the user actually + waited on if the slower side completed after the promise had + already resolved. + + Either side reporting `-` for its fields would mean its results + haven't been merged yet (only matters if you're reading partial state + in a debugger; the log only fires after both completed). A large + asymmetry between A and AAAA `work` (e.g., A=20 ms, AAAA=10000 ms) + is a textbook stub-resolver-drops-AAAA pattern, but it no longer + matters for the user's wait time — we resolved the promise off the + fast side. +- `system-resolver-join-pending` — a worker is already running + `getaddrinfo` for this name; we attached to its promise instead of + spawning a second worker. +- `async-query` — sent a query over our DNS socket. +- `join-pending` — joined an in-flight async DNS query for the same name. +- `repeat-timeout` / `no-conn-dnssec-rejected` — error paths. + +A consistent ~30 ms floor on `cache-hit` would indicate the cache is +not being short-circuited and we are paying lookup overhead per request. + +A `system-resolver-bg completed in N ms (worker)` line with a large `N` +no longer freezes the event loop — it just means that one cold lookup +took a long time. Other requests should keep flowing during it. + +### `UI wire-cookie:` — cookie-jar lookup time on the UI side + +``` +UI wire-cookie: get_cookie(URL) took N ms (N bytes returned) +``` + +Emitted by the UI process when `CookieJar::get_cookie` takes more than +5 ms. Pair this with the `cookie` field in `wire^:`: + +- High `wire^:` cookie + matching `UI wire-cookie:` ⇒ the jar itself is + slow. +- High `wire^:` cookie + no `UI wire-cookie:` ⇒ the UI process IPC + was scheduled late (UI process busy with something else), but the + jar lookup itself was fast. + +## Wire vs decoded — the foot-gun + +`wire X.X KiB` on the first line and the byte counts on the `wire+:` +line measure **different things**: + +- **wire bytes** = encoded body on the network. This is what dictates + network time. +- **decoded bytes** = bytes our consumer (the HTML parser, image + decoder, etc.) sees. This is what dictates CPU work after download. + +Comparing them gives you the compression ratio. Don't divide one by the +other's time and call it "throughput" — that's how you accidentally +report a network at 1.3 MB/s when the wire is doing 130 KB/s. + +## Reused-connection timing + +libcurl's phase markers (`namelookup`, `connect`, `appconnect`) report +**0** on a reused connection because no DNS / TCP / TLS work happened +again. The logger clamps each marker to the previous one's value so a +reused connection shows `dns 0 + tcp 0 + tls 0` and folds the queue +time into `queue` only. If you see a `req` value larger than zero on a +reused HTTP/2 / HTTP/3 connection, that is the time spent acquiring a +stream slot and writing the request, not redundant queue counting. + +## Patterns and what they mean + +| Symptom | Likely cause | +|---|---| +| One large `wire max gap` mid-transfer, low stall count, fast bytes either side (`wire++:`) | Server-side streaming / SSR with early flush. Origin sent the head, paused to generate the rest, then dumped it. Network is fine. | +| Many small stalls, low average throughput, no big gap (`wire++:`) | Bandwidth- or congestion-limited link, or HTTP/3 / TLS stack pacing. | +| Long single `wait` before any body, then everything fast (`wire:`) | Slow origin (server took its time computing the response). Not a network issue. | +| `wire thru` close to your link bandwidth, no stalls (`wire++:`) | You're saturating the pipe. Nothing to fix. | +| High `tls` on first request, `tls 0` afterwards (`wire:`) | Cold connection setup. Expected on first hit to a host. | +| Large `our-dns` with `dns 0` on `wire:` (`wire^:`) | Our DNS resolver is the bottleneck — libcurl reports 0 because we pre-resolved. Look at the resolver, not the network. | +| Large `cookie` (`wire^:`) | Cookie IPC round-trip to the UI process is slow — the UI process is busy or contended. | +| Non-zero `drain delay` (`wire^:`) | We noticed completion later than curl did — event-loop delay between curl's done-message landing and `check_active_requests` running. | +| `wire-batch:` followed by N `wire:` lines with the same timestamp prefix | Cosmetic clustering. The network completion times were spread out; only the logging happened in a tight loop. Trust the per-request phase numbers. | + +If `wire+` shows stalls but `wire++` doesn't, the network was steady and +curl's decompressor was batching — not interesting. If `wire++` shows +the stall too, it really happened on the wire and the gap text tells +you when in the transfer it landed. + +For a worked example of using these lines to diagnose a 1.5 s "slow +download" that turned out to be a 1062 ms server pause inside a +streaming-SSR response, see the discussion that originally added this +logging. + +## Where the code lives + +Most of this is implemented in `Services/RequestServer/Request.cpp`: + +- `log_network_activity` emits the `wire:` line. +- `record_chunk` populates the decoded-side `WireStats`; `log_chunk_stats` + emits the `wire+:` line. +- `on_xferinfo` (registered via `CURLOPT_XFERINFOFUNCTION`) populates the + wire-side fields; `log_chunk_stats` also emits the `wire++:` line. +- `mark_lifecycle_event` records pre-network timestamps from the state + handlers (`handle_dns_lookup_state`, `handle_retrieve_cookie_state`, + `notify_retrieved_http_cookie`, `handle_fetch_state`, + `handle_connect_state`); `log_chunk_stats` also emits the `wire^:` line. +- The per-request `WireStats` entry is created in the `Request` + constructors (so `created_at` is the true creation time) and removed + in `~Request`. + +Process-wide diagnostic lines: + +- `wire-batch:`, `wire-stall:`, `wire-burst:` are all in + `Services/RequestServer/ConnectionFromClient.cpp`. The stall and burst + detectors live at file scope as `note_event_tick`, `time_curl_call`, + and `burst_state_by_client`; they are invoked from each event-handler + entry point. +- `wire-pipe-pressure:` lives in `Request::write_queued_bytes_without_blocking` + in `Services/RequestServer/Request.cpp`. It also feeds the back-pressure + totals appended to `wire^:`. +- `LibDNS wire-dns:` lives in `Libraries/LibDNS/Resolver.h`, in + `Resolver::lookup` — a `ScopeGuard` around the function body times the + synchronous portion and classifies the resolution path. +- `UI wire-cookie:` lives in `Libraries/LibWebView/Application.cpp`, in + the `on_retrieve_http_cookie` callback set up by `launch_request_server`. + +All of the above lines are gated by the `REQUESTSERVER_WIRE_DEBUG` +debug macro (defined in `Meta/CMake/all_the_debug_macros.cmake`, +defaults to `ON`). To silence the whole subsystem at compile time, +set it to `OFF` and rebuild. Each individual line additionally +self-suppresses under its own threshold (100 ms event-loop gap, +50 ms curl call, 50 ms back-pressure window, 5 ms DNS sync, 5 ms +cookie jar) so even with the macro on, the log only fires when +something is interesting. Adjust the per-line thresholds in the +source if you want them tighter or louder. diff --git a/Libraries/LibDNS/Resolver.h b/Libraries/LibDNS/Resolver.h index 3f9f0f9c2d..efe38898a2 100644 --- a/Libraries/LibDNS/Resolver.h +++ b/Libraries/LibDNS/Resolver.h @@ -346,10 +346,33 @@ public: NonnullRefPtr>> lookup(ByteString name, Messages::Class class_, Vector desired_types, LookupOptions options = LookupOptions::default_()) { + // Instrumentation: classify how this lookup was satisfied (cache, system + // resolver fallback, async DNS query) and how long the synchronous portion + // of lookup() blocked the caller. Logs a `wire-dns:` line at exit. The + // synchronous portion is what blocks the event loop — anything > a few ms + // here is interesting because libcurl is sitting idle while we run. + auto lookup_entered_at = MonotonicTime::now(); + StringView lookup_path = "unknown"sv; + i64 sync_resolve_host_ms = -1; + auto log_lookup_on_exit = [&](StringView path) { + auto sync_ms = (MonotonicTime::now() - lookup_entered_at).to_milliseconds(); + if (sync_ms > 5 || sync_resolve_host_ms > 5) { + if (sync_resolve_host_ms >= 0) { + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "LibDNS wire-dns: lookup({}) path={} sync={} ms (system-resolve_host={} ms)", + name, path, sync_ms, sync_resolve_host_ms); + } else { + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "LibDNS wire-dns: lookup({}) path={} sync={} ms", + name, path, sync_ms); + } + } + }; + ScopeGuard log_guard = [&] { log_lookup_on_exit(lookup_path); }; + flush_cache(); if (options.repeating_lookup && options.repeating_lookup->times_repeated >= 5) { dbgln_if(DNS_DEBUG, "DNS: Repeating lookup for {} timed out", name); + lookup_path = "repeat-timeout"sv; auto promise = options.repeating_lookup->promise; promise->reject(Error::from_string_literal("DNS lookup timed out")); m_pending_lookups.with_write_locked([&](auto& lookups) { @@ -367,6 +390,7 @@ public: result->add_record({ .name = {}, .type = Messages::ResourceType::A, .class_ = Messages::Class::IN, .ttl = 0, .record = Messages::Records::A { maybe_ipv4.release_value() }, .raw = {} }); result->finished_request(); promise->resolve(move(result)); + lookup_path = "literal-ipv4"sv; return promise; } } @@ -378,6 +402,7 @@ public: result->add_record({ .name = {}, .type = Messages::ResourceType::AAAA, .class_ = Messages::Class::IN, .ttl = 0, .record = Messages::Records::AAAA { maybe_ipv6.release_value() }, .raw = {} }); result->finished_request(); promise->resolve(move(result)); + lookup_path = "literal-ipv6"sv; return promise; } } @@ -387,6 +412,7 @@ public: if (!options.validate_dnssec_locally || result->is_dnssec_validated()) { dbgln_if(DNS_DEBUG, "DNS: Resolved {} from cache", name); promise->resolve(result.release_nonnull()); + lookup_path = "cache-hit"sv; return promise; } dbgln_if(DNS_DEBUG, "DNS: Cache entry for {} is not DNSSEC validated (and we expect that), re-resolving", name); @@ -397,13 +423,20 @@ public: if (!has_connection()) { if (options.validate_dnssec_locally) { promise->reject(Error::from_string_literal("No connection available to validate DNSSEC")); + lookup_path = "no-conn-dnssec-rejected"sv; return promise; } // Use system resolver // FIXME: Use an underlying resolver instead. + // NB: Core::Socket::resolve_host is the BLOCKING getaddrinfo() fallback. If anything + // in this whole resolver path is going to freeze the event loop for many seconds, + // it is this call. We measure it explicitly so the wire-dns: line surfaces it. dbgln_if(DNS_DEBUG, "Not ready to resolve, using system resolver and skipping cache for {}", name); + lookup_path = "system-resolver"sv; + auto resolve_started_at = MonotonicTime::now(); auto record_or_error = Core::Socket::resolve_host(name, Core::Socket::SocketType::Stream); + sync_resolve_host_ms = (MonotonicTime::now() - resolve_started_at).to_milliseconds(); if (record_or_error.is_error()) { promise->reject(record_or_error.release_error()); return promise; @@ -425,6 +458,12 @@ public: return promise; } + // We arrive here only when an async DNS query will be sent over the wire. + // The synchronous portion still includes building the cache entry and + // serializing the query, but the actual wait happens asynchronously and + // is captured by RequestServer's `wire^:` line as `our-dns`. + lookup_path = "async-query"sv; + auto already_in_cache = false; auto result = m_cache.with_write_locked([&](auto& cache) -> NonnullRefPtr { dbgln_if(DNS_DEBUG, "DNS: Resolving {}...", name); @@ -564,6 +603,7 @@ public: if (cached_entry) { dbgln_if(DNS_DEBUG, "DNS::lookup({}) -> Lookup already underway", name); + lookup_path = "join-pending"sv; auto user_promise = Core::Promise>::construct(); promise->on_resolution = [user_promise, cached_promise = cached_entry->promise](auto& result) { user_promise->resolve(*result); diff --git a/Libraries/LibWebView/Application.cpp b/Libraries/LibWebView/Application.cpp index f0cf3a91d9..91575d9761 100644 --- a/Libraries/LibWebView/Application.cpp +++ b/Libraries/LibWebView/Application.cpp @@ -5,6 +5,7 @@ */ #include +#include #include #include #include @@ -507,8 +508,17 @@ ErrorOr Application::launch_request_server() { m_request_server_client = TRY(launch_request_server_process()); - m_request_server_client->on_retrieve_http_cookie = [this](URL::URL const& url) { - return m_cookie_jar->get_cookie(url, HTTP::Cookie::Source::Http); + m_request_server_client->on_retrieve_http_cookie = [this](URL::URL const& url) -> String { + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return m_cookie_jar->get_cookie(url, HTTP::Cookie::Source::Http); + auto started_at = MonotonicTime::now(); + auto cookie = m_cookie_jar->get_cookie(url, HTTP::Cookie::Source::Http); + auto elapsed_ms = (MonotonicTime::now() - started_at).to_milliseconds(); + if (elapsed_ms > 5) { + dbgln("UI wire-cookie: get_cookie({}) took {} ms ({} bytes returned)", + url, elapsed_ms, cookie.bytes().size()); + } + return cookie; }; m_request_server_client->on_request_server_died = [this]() { diff --git a/Meta/CMake/all_the_debug_macros.cmake b/Meta/CMake/all_the_debug_macros.cmake index 419131a966..394f22515e 100644 --- a/Meta/CMake/all_the_debug_macros.cmake +++ b/Meta/CMake/all_the_debug_macros.cmake @@ -55,6 +55,7 @@ set(PNG_DEBUG ON) set(PROMISE_DEBUG ON) set(REGEX_DEBUG ON) set(REQUESTSERVER_DEBUG ON) +set(REQUESTSERVER_WIRE_DEBUG ON) set(RESOURCE_DEBUG ON) set(RSA_PARSE_DEBUG ON) set(SHARED_QUEUE_DEBUG ON) diff --git a/Services/RequestServer/ConnectionFromClient.cpp b/Services/RequestServer/ConnectionFromClient.cpp index df68f6b9d0..5609898a64 100644 --- a/Services/RequestServer/ConnectionFromClient.cpp +++ b/Services/RequestServer/ConnectionFromClient.cpp @@ -28,6 +28,59 @@ namespace RequestServer { static ConnectionFromClient* g_primary_connection = nullptr; static IDAllocator s_client_ids; +static constexpr i64 TICK_GAP_THRESHOLD_MS = 100; +static Optional s_last_tick_at; +static StringView s_last_tick_label; + +// When libcurl asks us (via on_timeout_callback) to wake it up after N ms, we record when. If `curl-timer-fired` +// then runs close to that time the gap is by design (libcurl's heartbeat) and we suppress the wire-stall log. +static Optional s_curl_timer_due_at; +static constexpr i64 CURL_TIMER_ON_TIME_TOLERANCE_MS = 50; + +static void note_event_tick(StringView label) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return; + auto now = MonotonicTime::now(); + if (s_last_tick_at.has_value()) { + auto gap = (now - *s_last_tick_at).to_milliseconds(); + if (gap > TICK_GAP_THRESHOLD_MS) { + bool curl_timer_fired_on_schedule = false; + if (label == "curl-timer-fired"sv && s_curl_timer_due_at.has_value()) { + auto overshoot_ms = (now - *s_curl_timer_due_at).to_milliseconds(); + if (overshoot_ms >= -CURL_TIMER_ON_TIME_TOLERANCE_MS && overshoot_ms <= CURL_TIMER_ON_TIME_TOLERANCE_MS) + curl_timer_fired_on_schedule = true; + } + if (!curl_timer_fired_on_schedule) { + dbgln("RequestServer wire-stall: {} ms event-loop gap before '{}' (previous handler: '{}')", + gap, label, s_last_tick_label); + } + } + } + s_last_tick_at = now; + s_last_tick_label = label; +} + +static constexpr i64 CURL_CALL_THRESHOLD_MS = 50; +template +static auto time_curl_call(StringView label, F&& f) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return f(); + auto start = MonotonicTime::now(); + auto result = f(); + auto elapsed_ms = (MonotonicTime::now() - start).to_milliseconds(); + if (elapsed_ms > CURL_CALL_THRESHOLD_MS) + dbgln("RequestServer wire-stall: curl call '{}' took {} ms (synchronous in event loop)", label, elapsed_ms); + return result; +} + +// Per-client burst-of-requests counter. Tracks how many `start_request` IPC +// calls land in a tight window, so we can see if WebContent is dumping a +// page worth of requests on us in one shot. State lives on ConnectionFromClient. +static constexpr i64 BURST_WINDOW_MS = 100; +static constexpr u64 BURST_REPORT_THRESHOLD = 5; + ConnectionFromClient::ConnectionFromClient(NonnullOwnPtr transport, IsPrimaryConnection is_primary_connection, ConnectionMap& connections, Optional disk_cache) : IPC::ConnectionFromClient(*this, move(transport), s_client_ids.allocate()) , m_connections(connections) @@ -53,7 +106,11 @@ ConnectionFromClient::ConnectionFromClient(NonnullOwnPtr transpo set_option(CURLMOPT_TIMERDATA, this); m_timer = Core::Timer::create_single_shot(0, [this] { - auto result = curl_multi_socket_action(m_curl_multi, CURL_SOCKET_TIMEOUT, 0, nullptr); + note_event_tick("curl-timer-fired"sv); + s_curl_timer_due_at = {}; + auto result = time_curl_call("multi_socket_action(timeout)"sv, [this] { + return curl_multi_socket_action(m_curl_multi, CURL_SOCKET_TIMEOUT, 0, nullptr); + }); VERIFY(result == CURLM_OK); check_active_requests(); }); @@ -201,14 +258,30 @@ void ConnectionFromClient::set_use_system_dns() void ConnectionFromClient::start_request(u64 request_id, ByteString method, URL::URL url, Vector request_headers, ByteBuffer request_body, HTTP::CacheMode cache_mode, HTTP::Cookie::IncludeCredentials include_credentials, Core::ProxyData proxy_data) { + note_event_tick("ipc-start-request"sv); dbgln_if(REQUESTSERVER_DEBUG, "RequestServer: start_request({}, {})", request_id, url); + if constexpr (REQUESTSERVER_WIRE_DEBUG) { + auto now = MonotonicTime::now(); + if (m_burst_window_started_at.has_value() && (now - *m_burst_window_started_at).to_milliseconds() < BURST_WINDOW_MS) { + ++m_requests_in_burst_window; + } else { + if (m_requests_in_burst_window > BURST_REPORT_THRESHOLD) { + dbgln("RequestServer wire-burst: client {} sent {} requests in <{} ms", + client_id(), m_requests_in_burst_window, BURST_WINDOW_MS); + } + m_burst_window_started_at = now; + m_requests_in_burst_window = 1; + } + } + auto request = Request::fetch(request_id, m_disk_cache, cache_mode, *this, m_curl_multi, m_resolver, move(url), move(method), HTTP::HeaderList::create(move(request_headers)), move(request_body), include_credentials, m_alt_svc_cache_path, proxy_data); m_active_requests.set(request_id, move(request)); } void ConnectionFromClient::start_revalidation_request(Badge, ByteString method, URL::URL url, NonnullRefPtr request_headers, ByteBuffer request_body, HTTP::Cookie::IncludeCredentials include_credentials, Core::ProxyData proxy_data) { + note_event_tick("ipc-start-revalidation"sv); auto request_id = m_next_revalidation_request_id++; dbgln_if(REQUESTSERVER_DEBUG, "RequestServer: start_revalidation_request({}, {})", request_id, url); @@ -237,7 +310,10 @@ int ConnectionFromClient::on_socket_callback(CURL*, int sockfd, int what, void* auto& notifier = notifiers.ensure(sockfd, [client, sockfd, multi = client->m_curl_multi, type, select_flag] { auto notifier = Core::Notifier::construct(sockfd, type); notifier->on_activation = [client, sockfd, multi, select_flag] { - auto result = curl_multi_socket_action(multi, sockfd, select_flag, nullptr); + note_event_tick("curl-socket-ready"sv); + auto result = time_curl_call("multi_socket_action(socket)"sv, [&] { + return curl_multi_socket_action(multi, sockfd, select_flag, nullptr); + }); VERIFY(result == CURLM_OK); client->check_active_requests(); @@ -261,17 +337,22 @@ int ConnectionFromClient::on_timeout_callback(void*, long timeout_ms, void* user if (!client->m_timer) return 0; - if (timeout_ms < 0) + if (timeout_ms < 0) { client->m_timer->stop(); - else + s_curl_timer_due_at = {}; + } else { client->m_timer->restart(timeout_ms); + s_curl_timer_due_at = MonotonicTime::now() + AK::Duration::from_milliseconds(timeout_ms); + } return 0; } void ConnectionFromClient::check_active_requests() { + note_event_tick("check-active-requests"sv); int msgs_in_queue = 0; + u64 completions_drained = 0; while (auto* msg = curl_multi_info_read(m_curl_multi, &msgs_in_queue)) { if (msg->msg != CURLMSG_DONE) continue; @@ -293,9 +374,13 @@ void ConnectionFromClient::check_active_requests() continue; } + ++completions_drained; auto* request = static_cast(application_private); request->notify_fetch_complete({}, msg->data.result); } + + if (completions_drained > 1) + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire-batch: drained {} completions in one curl multi tick", completions_drained); } Messages::RequestServer::StopRequestResponse ConnectionFromClient::stop_request(u64 request_id) @@ -325,6 +410,7 @@ void ConnectionFromClient::ensure_connection(u64 request_id, URL::URL url, ::Req void ConnectionFromClient::retrieved_http_cookie(int client_id, u64 request_id, RequestServer::RequestType request_type, String cookie) { + note_event_tick("ipc-retrieved-cookie"sv); if (auto connection = m_connections.get(client_id); connection.has_value()) { auto request = [&]() { switch (request_type) { diff --git a/Services/RequestServer/ConnectionFromClient.h b/Services/RequestServer/ConnectionFromClient.h index 3f1eff9f0b..34035924e0 100644 --- a/Services/RequestServer/ConnectionFromClient.h +++ b/Services/RequestServer/ConnectionFromClient.h @@ -8,6 +8,8 @@ #include #include +#include +#include #include #include #include @@ -91,6 +93,9 @@ private: ByteString m_alt_svc_cache_path; u64 m_next_revalidation_request_id { 0 }; + + Optional m_burst_window_started_at; + u64 m_requests_in_burst_window { 0 }; }; constexpr inline uintptr_t websocket_private_tag = 0x1; diff --git a/Services/RequestServer/Request.cpp b/Services/RequestServer/Request.cpp index 3694bac878..19a08be61a 100644 --- a/Services/RequestServer/Request.cpp +++ b/Services/RequestServer/Request.cpp @@ -6,6 +6,7 @@ */ #include +#include #include #include #include @@ -25,6 +26,336 @@ extern OwnPtr g_resource_substitution_map; static long s_connect_timeout_seconds = 90L; +static void log_network_activity(URL::URL const& url, ByteString const& method, void* curl_easy_handle, int curl_result_code, bool is_revalidation, RequestType type) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return; + if (!curl_easy_handle) + return; + + auto get_off = [&](auto option) { + curl_off_t value = 0; + (void)curl_easy_getinfo(curl_easy_handle, option, &value); + return value; + }; + auto get_long = [&](auto option) { + long value = 0; + (void)curl_easy_getinfo(curl_easy_handle, option, &value); + return value; + }; + + long http_status = get_long(CURLINFO_RESPONSE_CODE); + long http_version = get_long(CURLINFO_HTTP_VERSION); + + auto queue_us = get_off(CURLINFO_QUEUE_TIME_T); + auto namelookup_us = get_off(CURLINFO_NAMELOOKUP_TIME_T); + auto connect_us = get_off(CURLINFO_CONNECT_TIME_T); + auto appconnect_us = get_off(CURLINFO_APPCONNECT_TIME_T); + auto pretransfer_us = get_off(CURLINFO_PRETRANSFER_TIME_T); + auto starttransfer_us = get_off(CURLINFO_STARTTRANSFER_TIME_T); + auto total_us = get_off(CURLINFO_TOTAL_TIME_T); + auto bytes_downloaded = get_off(CURLINFO_SIZE_DOWNLOAD_T); + auto bytes_uploaded = get_off(CURLINFO_SIZE_UPLOAD_T); + auto download_speed_bps = get_off(CURLINFO_SPEED_DOWNLOAD_T); + + // libcurl phase timings are cumulative from t=0, but skipped phases (e.g. DNS/TCP/TLS on a + // reused connection) are reported as 0, breaking the monotonic ordering. Clamp each marker + // to the previous one so skipped phases yield a 0-length delta instead of double-counting. + auto clamp = [](curl_off_t marker, curl_off_t previous) { return marker > previous ? marker : previous; }; + auto m_queue = queue_us; + auto m_namelookup = clamp(namelookup_us, m_queue); + auto m_connect = clamp(connect_us, m_namelookup); + auto m_appconnect = clamp(appconnect_us, m_connect); + auto m_pretransfer = clamp(pretransfer_us, m_appconnect); + auto m_starttransfer = clamp(starttransfer_us, m_pretransfer); + auto m_total = clamp(total_us, m_starttransfer); + + auto us_to_ms = [](curl_off_t us) { return static_cast(us) / 1000.0; }; + auto queue_ms = us_to_ms(m_queue); + auto dns_ms = us_to_ms(m_namelookup - m_queue); + auto tcp_ms = us_to_ms(m_connect - m_namelookup); + auto tls_ms = us_to_ms(m_appconnect - m_connect); + auto request_ms = us_to_ms(m_pretransfer - m_appconnect); + auto wait_ms = us_to_ms(m_starttransfer - m_pretransfer); + auto body_ms = us_to_ms(m_total - m_starttransfer); + auto total_ms = us_to_ms(m_total); + + auto kib = [](curl_off_t bytes) { return static_cast(bytes) / 1024.0; }; + + StringView http_version_str = "HTTP/?"sv; + switch (http_version) { + case CURL_HTTP_VERSION_1_0: + http_version_str = "HTTP/1.0"sv; + break; + case CURL_HTTP_VERSION_1_1: + http_version_str = "HTTP/1.1"sv; + break; + case CURL_HTTP_VERSION_2_0: + http_version_str = "HTTP/2"sv; + break; + case CURL_HTTP_VERSION_3: + http_version_str = "HTTP/3"sv; + break; + default: + break; + } + + StringView kind; + if (curl_result_code != CURLE_OK) + kind = "FAIL"sv; + else if (is_revalidation && http_status == 304) + kind = "REVAL-304"sv; + else if (is_revalidation) + kind = "REVAL-FULL"sv; + else + kind = "DOWNLOAD"sv; + + StringView background = type == RequestType::BackgroundRevalidation ? " [bg]"sv : ""sv; + + if (curl_result_code != CURLE_OK) { + char const* err = curl_easy_strerror(static_cast(curl_result_code)); + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire: {}{} {} {} -> error: {} (after {:.1} ms, wire {:.1} KiB)", + kind, background, method, url, err, total_ms, kib(bytes_downloaded)); + return; + } + + auto wire_kibps_during_body = body_ms > 0.0 + ? kib(bytes_downloaded) / (body_ms / 1000.0) + : 0.0; + + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire: {}{} {} {} {} -> {} | wire {:.1} KiB sent {:.1} KiB | total {:.1} ms = queue {:.1} + dns {:.1} + tcp {:.1} + tls {:.1} + req {:.1} + wait {:.1} + body {:.1} | wire {:.1} KiB/s avg, {:.1} KiB/s during body", + kind, background, method, url, http_version_str, http_status, + kib(bytes_downloaded), kib(bytes_uploaded), + total_ms, queue_ms, dns_ms, tcp_ms, tls_ms, request_ms, wait_ms, body_ms, + kib(download_speed_bps), wire_kibps_during_body); +} + +struct WireStats { + // Decoded-side (sampled in on_data_received, after curl decompresses) + Optional first_chunk_at; + Optional last_chunk_at; + u64 chunk_count { 0 }; + u64 total_decoded_bytes { 0 }; + u64 min_chunk_bytes { NumericLimits::max() }; + u64 max_chunk_bytes { 0 }; + AK::Duration sum_inter_chunk_gaps; + AK::Duration max_inter_chunk_gap; + u64 stall_count_100ms { 0 }; + AK::Duration max_stall_started_at; + u64 bytes_at_max_stall { 0 }; + + // Wire-side (sampled in CURLOPT_XFERINFOFUNCTION, before decompression) + Optional first_wire_byte_at; + Optional last_wire_byte_at; + curl_off_t last_wire_dlnow { 0 }; + AK::Duration max_wire_gap; + AK::Duration max_wire_stall_started_at; + curl_off_t wire_bytes_at_max_stall { 0 }; + u64 wire_stall_count_100ms { 0 }; + + // Internal-pipeline lifecycle (set by state-machine handlers). + // Lets us see how much wall time we burned in our own code paths + // (cache lookup, our DNS resolver, cookie IPC, curl setup) before + // libcurl ever saw the request. + Optional created_at; + Optional dns_started_at; + Optional dns_completed_at; + Optional cookie_started_at; + Optional cookie_completed_at; + Optional curl_added_at; + Optional complete_observed_at; + + // WebContent-side back-pressure on our outgoing pipe. Updated by + // write_queued_bytes_without_blocking when the pipe returns EAGAIN + // (WebContent isn't draining fast enough — typically because its main + // thread is busy parsing, running JS, etc.). `current_window_started` + // is set on entry to a back-pressure window and cleared when we resume + // writing successfully. + Optional current_pressure_window_started; + AK::Duration total_pipe_back_pressure; + u64 pipe_back_pressure_events { 0 }; + u64 max_buffered_bytes { 0 }; +}; + +static HashMap& wire_stats() +{ + static HashMap map; + return map; +} + +static void record_chunk(Request const* request, size_t bytes) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return; + auto now = MonotonicTime::now(); + auto& stats = wire_stats().ensure(request); + + if (stats.chunk_count == 0) { + stats.first_chunk_at = now; + } else { + auto gap = now - *stats.last_chunk_at; + stats.sum_inter_chunk_gaps = stats.sum_inter_chunk_gaps + gap; + if (gap > stats.max_inter_chunk_gap) { + stats.max_inter_chunk_gap = gap; + stats.max_stall_started_at = *stats.last_chunk_at - *stats.first_chunk_at; + stats.bytes_at_max_stall = stats.total_decoded_bytes; + } + if (gap > AK::Duration::from_milliseconds(100)) + stats.stall_count_100ms += 1; + } + + stats.last_chunk_at = now; + stats.chunk_count += 1; + stats.total_decoded_bytes += bytes; + if (bytes < stats.min_chunk_bytes) + stats.min_chunk_bytes = bytes; + if (bytes > stats.max_chunk_bytes) + stats.max_chunk_bytes = bytes; +} + +[[maybe_unused]] static int on_xferinfo(void* user_data, curl_off_t /*dltotal*/, curl_off_t dlnow, curl_off_t /*ultotal*/, curl_off_t /*ulnow*/) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return 0; + auto* request = static_cast(user_data); + if (dlnow <= 0) + return 0; + + auto& stats = wire_stats().ensure(request); + if (dlnow == stats.last_wire_dlnow) + return 0; + + auto now = MonotonicTime::now(); + if (!stats.first_wire_byte_at.has_value()) + stats.first_wire_byte_at = now; + if (stats.last_wire_byte_at.has_value()) { + auto gap = now - *stats.last_wire_byte_at; + if (gap > stats.max_wire_gap) { + stats.max_wire_gap = gap; + stats.max_wire_stall_started_at = *stats.last_wire_byte_at - *stats.first_wire_byte_at; + stats.wire_bytes_at_max_stall = stats.last_wire_dlnow; + } + if (gap > AK::Duration::from_milliseconds(100)) + stats.wire_stall_count_100ms += 1; + } + stats.last_wire_byte_at = now; + stats.last_wire_dlnow = dlnow; + return 0; +} + +static void log_chunk_stats(Request const* request) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return; + auto it = wire_stats().find(request); + if (it == wire_stats().end()) + return; + auto const& s = it->value; + if (s.chunk_count == 0) + return; + + auto kib = [](u64 b) { return static_cast(b) / 1024.0; }; + auto kib_off = [](curl_off_t b) { return static_cast(b) / 1024.0; }; + auto decoded_span = (s.last_chunk_at.has_value() && s.first_chunk_at.has_value()) + ? *s.last_chunk_at - *s.first_chunk_at + : AK::Duration {}; + auto decoded_span_ms = decoded_span.to_milliseconds(); + auto avg_gap_ms = s.chunk_count > 1 + ? static_cast(s.sum_inter_chunk_gaps.to_microseconds()) / 1000.0 / static_cast(s.chunk_count - 1) + : 0.0; + auto avg_chunk = s.total_decoded_bytes / s.chunk_count; + auto decoded_kibps = decoded_span_ms > 0 + ? kib(s.total_decoded_bytes) / (static_cast(decoded_span_ms) / 1000.0) + : 0.0; + + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire+: decoded chunks={} bytes={:.1} KiB span={} ms thru={:.1} KiB/s | gap avg={:.1} ms max={} ms stalls(>100ms)={} | worst gap began at +{} ms after {:.1} KiB decoded | chunk bytes avg={} min={} max={}", + s.chunk_count, kib(s.total_decoded_bytes), decoded_span_ms, decoded_kibps, + avg_gap_ms, s.max_inter_chunk_gap.to_milliseconds(), s.stall_count_100ms, + s.max_stall_started_at.to_milliseconds(), kib(s.bytes_at_max_stall), + avg_chunk, s.min_chunk_bytes, s.max_chunk_bytes); + + if (s.first_wire_byte_at.has_value() && s.last_wire_byte_at.has_value()) { + auto wire_span = *s.last_wire_byte_at - *s.first_wire_byte_at; + auto wire_span_ms = wire_span.to_milliseconds(); + auto wire_kibps = wire_span_ms > 0 + ? kib_off(s.last_wire_dlnow) / (static_cast(wire_span_ms) / 1000.0) + : 0.0; + auto compression_ratio = s.last_wire_dlnow > 0 + ? static_cast(s.total_decoded_bytes) / static_cast(s.last_wire_dlnow) + : 0.0; + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire++: wire bytes={:.1} KiB span={} ms thru={:.1} KiB/s | wire max gap={} ms stalls(>100ms)={} | worst wire gap began at +{} ms after {:.1} KiB on the wire | compression={:.2}x", + kib_off(s.last_wire_dlnow), wire_span_ms, wire_kibps, + s.max_wire_gap.to_milliseconds(), s.wire_stall_count_100ms, + s.max_wire_stall_started_at.to_milliseconds(), kib_off(s.wire_bytes_at_max_stall), + compression_ratio); + } + + // wire^: pre-network time spent inside RequestServer (cache + our DNS resolver + cookie IPC + // + curl setup), and the gap between the wire going quiet and us actually emitting this log + // entry. Useful to see if a long "total" was actually our pipeline rather than the network. + if (s.created_at.has_value()) { + auto delta_ms = [](Optional const& a, Optional const& b) -> i64 { + if (!a.has_value() || !b.has_value()) + return -1; + return (*b - *a).to_milliseconds(); + }; + + // Cache + Init + WaitForCache: from creation to start of DNS lookup. + auto pre_dns_ms = delta_ms(s.created_at, s.dns_started_at); + // Our DNS resolver (note: distinct from libcurl's `dns` field, which is 0 because we + // pre-resolve and pass via CURLOPT_RESOLVE). + auto our_dns_ms = delta_ms(s.dns_started_at, s.dns_completed_at); + // Cookie IPC round-trip to the UI process. + auto cookie_ms = delta_ms(s.cookie_started_at, s.cookie_completed_at); + // Time from the last completed pre-network step to curl_multi_add_handle. + auto curl_setup_ms = [&]() -> i64 { + Optional last_pre_curl; + if (s.cookie_completed_at.has_value()) + last_pre_curl = s.cookie_completed_at; + else if (s.dns_completed_at.has_value()) + last_pre_curl = s.dns_completed_at; + else + last_pre_curl = s.created_at; + return delta_ms(last_pre_curl, s.curl_added_at); + }(); + auto pre_curl_total_ms = delta_ms(s.created_at, s.curl_added_at); + + // Drain delay: time between the last byte arriving and check_active_requests draining + // the completion. Non-zero would mean we noticed completion later than curl did. + Optional last_activity; + if (s.last_wire_byte_at.has_value()) + last_activity = s.last_wire_byte_at; + else if (s.last_chunk_at.has_value()) + last_activity = s.last_chunk_at; + auto drain_delay_ms = delta_ms(last_activity, s.complete_observed_at); + + auto fmt_ms = [](i64 ms) -> ByteString { + return ms < 0 ? ByteString { "-" } : ByteString::formatted("{}", ms); + }; + + ByteString back_pressure_summary; + if (s.pipe_back_pressure_events > 0) { + back_pressure_summary = ByteString::formatted( + " | pipe back-pressure events={} total={} ms peak-buffered={} bytes", + s.pipe_back_pressure_events, + s.total_pipe_back_pressure.to_milliseconds(), + s.max_buffered_bytes); + } + + dbgln_if(REQUESTSERVER_WIRE_DEBUG, "RequestServer wire^: internal pre-curl={} ms = cache+init {} + our-dns {} + cookie {} + curl-setup {} | drain delay {} ms{}", + fmt_ms(pre_curl_total_ms), fmt_ms(pre_dns_ms), fmt_ms(our_dns_ms), + fmt_ms(cookie_ms), fmt_ms(curl_setup_ms), fmt_ms(drain_delay_ms), + back_pressure_summary); + } +} + +static void mark_lifecycle_event(Request const* request, Optional WireStats::* field) +{ + if constexpr (!REQUESTSERVER_WIRE_DEBUG) + return; + wire_stats().ensure(request).*field = MonotonicTime::now(); +} + NonnullOwnPtr Request::fetch( u64 request_id, Optional disk_cache, @@ -119,6 +450,8 @@ Request::Request( , m_proxy_data(proxy_data) , m_response_headers(HTTP::HeaderList::create()) { + if constexpr (REQUESTSERVER_WIRE_DEBUG) + wire_stats().ensure(this).created_at = MonotonicTime::now(); } Request::Request( @@ -136,6 +469,8 @@ Request::Request( , m_request_headers(HTTP::HeaderList::create()) , m_response_headers(HTTP::HeaderList::create()) { + if constexpr (REQUESTSERVER_WIRE_DEBUG) + wire_stats().ensure(this).created_at = MonotonicTime::now(); } Request::~Request() @@ -159,6 +494,9 @@ Request::~Request() else m_cache_entry_writer->remove_incomplete_entry(); } + + if constexpr (REQUESTSERVER_WIRE_DEBUG) + wire_stats().remove(this); } void Request::notify_request_unblocked(Badge) @@ -170,6 +508,8 @@ void Request::notify_request_unblocked(Badge) void Request::notify_retrieved_http_cookie(Badge, StringView cookie) { + mark_lifecycle_event(this, &WireStats::cookie_completed_at); + if (!cookie.is_empty()) { auto header = HTTP::Header::isomorphic_encode("Cookie"sv, cookie); m_request_headers->append(move(header)); @@ -180,6 +520,13 @@ void Request::notify_retrieved_http_cookie(Badge, StringVi void Request::notify_fetch_complete(Badge, int result_code) { + mark_lifecycle_event(this, &WireStats::complete_observed_at); + + if (m_type == RequestType::Fetch || m_type == RequestType::BackgroundRevalidation) { + log_network_activity(m_url, m_method, m_curl_easy_handle, result_code, is_revalidation_request(), m_type); + log_chunk_stats(this); + } + if (is_revalidation_request()) { if (acquire_status_code() == 304) { if (m_type == RequestType::BackgroundRevalidation && m_disk_cache->mode() == HTTP::DiskCache::Mode::Testing) @@ -435,13 +782,17 @@ void Request::handle_dns_lookup_state() auto host = m_url.serialized_host().to_byte_string(); auto const& dns_info = DNSInfo::the(); + mark_lifecycle_event(this, &WireStats::dns_started_at); + m_resolver->dns.lookup(host, DNS::Messages::Class::IN, { DNS::Messages::ResourceType::A, DNS::Messages::ResourceType::AAAA }, { .validate_dnssec_locally = dns_info.validate_dnssec_locally }) ->when_rejected(weak_callback(*this, [host](auto& self, auto const& error) { + mark_lifecycle_event(&self, &WireStats::dns_completed_at); dbgln("Request::handle_dns_lookup_state: DNS lookup failed for '{}': {}", host, error); self.m_network_error = Requests::NetworkError::UnableToResolveHost; self.transition_to_state(State::Error); })) .when_resolved(weak_callback(*this, [host](auto& self, NonnullRefPtr dns_result) { + mark_lifecycle_event(&self, &WireStats::dns_completed_at); if (dns_result->is_empty() || !dns_result->has_cached_addresses()) { dbgln("Request::handle_dns_lookup_state: DNS lookup failed for '{}'", host); self.m_network_error = Requests::NetworkError::UnableToResolveHost; @@ -463,6 +814,7 @@ void Request::handle_retrieve_cookie_state() } if (auto connection = ConnectionFromClient::primary_connection(); connection.has_value()) { + mark_lifecycle_event(this, &WireStats::cookie_started_at); connection->async_retrieve_http_cookie(m_client.client_id(), m_request_id, m_type, m_url); } else { m_network_error = Requests::NetworkError::RequestServerDied; @@ -492,6 +844,7 @@ void Request::handle_connect_state() set_option(CURLOPT_CONNECTTIMEOUT, s_connect_timeout_seconds); set_option(CURLOPT_CONNECT_ONLY, 1L); + mark_lifecycle_event(this, &WireStats::curl_added_at); auto result = curl_multi_add_handle(m_curl_multi_handle, m_curl_easy_handle); VERIFY(result == CURLM_OK); } @@ -601,6 +954,12 @@ void Request::handle_fetch_state() set_option(CURLOPT_WRITEFUNCTION, &on_data_received); set_option(CURLOPT_WRITEDATA, this); + if constexpr (REQUESTSERVER_WIRE_DEBUG) { + set_option(CURLOPT_NOPROGRESS, 0L); + set_option(CURLOPT_XFERINFOFUNCTION, &on_xferinfo); + set_option(CURLOPT_XFERINFODATA, this); + } + VERIFY(m_dns_result); auto formatted_address = build_curl_resolve_list(*m_dns_result, m_url.serialized_host(), m_url.port_or_default()); @@ -611,6 +970,7 @@ void Request::handle_fetch_state() VERIFY_NOT_REACHED(); } + mark_lifecycle_event(this, &WireStats::curl_added_at); auto result = curl_multi_add_handle(m_curl_multi_handle, m_curl_easy_handle); VERIFY(result == CURLM_OK); } @@ -696,6 +1056,9 @@ size_t Request::on_data_received(void* buffer, size_t size, size_t nmemb, void* { auto& request = *static_cast(user_data); + if (request.m_type == RequestType::Fetch || request.m_type == RequestType::BackgroundRevalidation) + record_chunk(&request, size * nmemb); + if (request.is_revalidation_request()) { // If we arrive here, we did not receive an HTTP 304 response code. We must remove the cache entry and inform // the client of the new response headers and data. @@ -822,6 +1185,19 @@ ErrorOr Request::write_queued_bytes_without_blocking() }); } + if constexpr (REQUESTSERVER_WIRE_DEBUG) { + auto& stats = wire_stats().ensure(this); + if (stats.current_pressure_window_started.has_value()) { + auto window = MonotonicTime::now() - *stats.current_pressure_window_started; + stats.total_pipe_back_pressure = stats.total_pipe_back_pressure + window; + stats.current_pressure_window_started = {}; + if (window.to_milliseconds() > 50) { + dbgln("RequestServer wire-pipe-pressure: {} {} unblocked after {} ms (peak buffered={} bytes); WebContent likely behind", + m_method, m_url, window.to_milliseconds(), stats.max_buffered_bytes); + } + } + } + while (!m_response_buffer.is_eof()) { auto bytes = m_response_buffer.peek_some_contiguous(); @@ -830,6 +1206,18 @@ ErrorOr Request::write_queued_bytes_without_blocking() if (!first_is_one_of(result.error().code(), EAGAIN, EWOULDBLOCK)) return result.release_error(); + if constexpr (REQUESTSERVER_WIRE_DEBUG) { + auto& stats = wire_stats().ensure(this); + if (!stats.current_pressure_window_started.has_value()) { + stats.current_pressure_window_started = MonotonicTime::now(); + stats.pipe_back_pressure_events += 1; + dbgln("RequestServer wire-pipe-pressure: {} {} pipe full, buffering={} bytes", + m_method, m_url, m_response_buffer.used_buffer_size()); + } + if (m_response_buffer.used_buffer_size() > stats.max_buffered_bytes) + stats.max_buffered_bytes = m_response_buffer.used_buffer_size(); + } + m_client_writer_notifier->set_enabled(true); return {}; }