dmaax/ladybird
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

RequestServer: Add diagnostic wire-activity logging

Browse source 
Per-request and per-connection logging that surfaces enough detail
to diagnose where time goes when a page load misbehaves. Gated by a
new REQUESTSERVER_WIRE_DEBUG cmakedefine.

Documentation/RequestServerWireLogging.md describes each label
(wire/wire+/wire++/wire^, wire-batch, wire-stall, wire-burst,
wire-pipe-pressure, LibDNS wire-dns, UI wire-cookie) and how to read
them.
This commit is contained in:
Andreas Kling 2026-04-26 06:56:19 +02:00 committed by Andreas Kling
parent 7beac55210
commit 072a3bdb90
8 changed files with 949 additions and 6 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
AK/Debug.h.in
View file

@ -238,6 +238,10 @@
# cmakedefine01 REQUESTSERVER_DEBUG
#endif
#ifndef REQUESTSERVER_WIRE_DEBUG
# cmakedefine01 REQUESTSERVER_WIRE_DEBUG
#endif
#ifndef RESOURCE_DEBUG
# cmakedefine01 RESOURCE_DEBUG
#endif

409
Documentation/RequestServerWireLogging.md Normal file
View file

@ -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: <curl message> (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.

40
Libraries/LibDNS/Resolver.h
View file

@ -346,10 +346,33 @@ public:
NonnullRefPtr<Core::Promise<NonnullRefPtr<LookupResult const>>> lookup(ByteString name, Messages::Class class_, Vector<Messages::ResourceType> 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<LookupResult> {
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<NonnullRefPtr<LookupResult const>>::construct();
promise->on_resolution = [user_promise, cached_promise = cached_entry->promise](auto& result) {
user_promise->resolve(*result);

14
Libraries/LibWebView/Application.cpp
View file

@ -5,6 +5,7 @@
*/
#include <AK/Debug.h>
#include <AK/Time.h>
#include <LibCore/ArgsParser.h>
#include <LibCore/Environment.h>
#include <LibCore/StandardPaths.h>
@ -507,8 +508,17 @@ ErrorOr<void> 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]() {

1
Meta/CMake/all_the_debug_macros.cmake
View file

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

94
Services/RequestServer/ConnectionFromClient.cpp
View file

@ -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<MonotonicTime> 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<MonotonicTime> 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<typename F>
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<IPC::Transport> transport, IsPrimaryConnection is_primary_connection, ConnectionMap& connections, Optional<HTTP::DiskCache&> disk_cache)
: IPC::ConnectionFromClient<RequestClientEndpoint, RequestServerEndpoint>(*this, move(transport), s_client_ids.allocate())
, m_connections(connections)
@ -53,7 +106,11 @@ ConnectionFromClient::ConnectionFromClient(NonnullOwnPtr<IPC::Transport> 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<HTTP::Header> 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<Request>, ByteString method, URL::URL url, NonnullRefPtr<HTTP::HeaderList> 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<Request*>(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) {

5
Services/RequestServer/ConnectionFromClient.h
View file

@ -8,6 +8,8 @@
#include <AK/Badge.h>
#include <AK/HashMap.h>
#include <AK/Optional.h>
#include <AK/Time.h>
#include <LibHTTP/Cache/CacheMode.h>
#include <LibHTTP/Cache/DiskCacheSettings.h>
#include <LibHTTP/Forward.h>
@ -91,6 +93,9 @@ private:
ByteString m_alt_svc_cache_path;
u64 m_next_revalidation_request_id { 0 };
Optional<MonotonicTime> m_burst_window_started_at;
u64 m_requests_in_burst_window { 0 };
};
constexpr inline uintptr_t websocket_private_tag = 0x1;

388
Services/RequestServer/Request.cpp
View file

@ -6,6 +6,7 @@
*/
#include <AK/GenericShorthands.h>
#include <AK/HashMap.h>
#include <LibCore/File.h>
#include <LibCore/MimeData.h>
#include <LibCore/Notifier.h>
@ -25,6 +26,336 @@ extern OwnPtr<ResourceSubstitutionMap> 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<double>(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<double>(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<CURLcode>(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<MonotonicTime> first_chunk_at;
Optional<MonotonicTime> last_chunk_at;
u64 chunk_count { 0 };
u64 total_decoded_bytes { 0 };
u64 min_chunk_bytes { NumericLimits<u64>::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<MonotonicTime> first_wire_byte_at;
Optional<MonotonicTime> 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<MonotonicTime> created_at;
Optional<MonotonicTime> dns_started_at;
Optional<MonotonicTime> dns_completed_at;
Optional<MonotonicTime> cookie_started_at;
Optional<MonotonicTime> cookie_completed_at;
Optional<MonotonicTime> curl_added_at;
Optional<MonotonicTime> 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<MonotonicTime> current_pressure_window_started;
AK::Duration total_pipe_back_pressure;
u64 pipe_back_pressure_events { 0 };
u64 max_buffered_bytes { 0 };
};
static HashMap<Request const*, WireStats>& wire_stats()
{
static HashMap<Request const*, WireStats> 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<Request const*>(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<double>(b) / 1024.0; };
auto kib_off = [](curl_off_t b) { return static_cast<double>(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<double>(s.sum_inter_chunk_gaps.to_microseconds()) / 1000.0 / static_cast<double>(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<double>(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<double>(wire_span_ms) / 1000.0)
: 0.0;
auto compression_ratio = s.last_wire_dlnow > 0
? static_cast<double>(s.total_decoded_bytes) / static_cast<double>(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<MonotonicTime> const& a, Optional<MonotonicTime> 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<MonotonicTime> 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<MonotonicTime> 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<MonotonicTime> WireStats::* field)
{
if constexpr (!REQUESTSERVER_WIRE_DEBUG)
return;
wire_stats().ensure(request).*field = MonotonicTime::now();
}
NonnullOwnPtr<Request> Request::fetch(
u64 request_id,
Optional<HTTP::DiskCache&> 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<HTTP::DiskCache>)
@ -170,6 +508,8 @@ void Request::notify_request_unblocked(Badge<HTTP::DiskCache>)
void Request::notify_retrieved_http_cookie(Badge<ConnectionFromClient>, 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<ConnectionFromClient>, StringVi
void Request::notify_fetch_complete(Badge<ConnectionFromClient>, 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::LookupResult const> 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<Request*>(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<void> 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<void> 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 {};
}