Source code
Revision control
Copy as Markdown
Other Tools
Test Info:
/* Any copyright is dedicated to the Public Domain.
"use strict";
// the same channel, so pairing the first with the last would count the interval
// between attempts into dns, connect and send at once. nsITimedChannel keeps
// them per attempt, which is where the phases come from.
//
// The fixtures are the reporter's HAR entry 0 (attachment 9631898) and the pcap
// it came from (attachment 9631899): a request that really took 10558ms,
// reported as dns 10163, connect 10238, send 10246, total 20720.
const { NetworkTimings } = ChromeUtils.importESModule(
"resource://devtools/shared/network-observer/NetworkTimings.sys.mjs"
);
// Microseconds. The attempt that sent its 0-RTT data and stalled until the
// server reset the connection, then the attempt that served the request.
const REQUEST_START = 0;
const FAILED = {
resolving: 1000,
resolved: 1500,
connecting: 1600,
connected: 83_000,
sending: 84_600,
};
const SERVING = {
resolving: 10_120_000,
resolved: 10_164_000,
connecting: 10_161_000,
connected: 10_239_600,
tlsStarting: 10_239_600,
tlsEnding: 10_330_600,
sending: 10_330_600,
};
const RESPONSE_START = 10_521_600;
const RESPONSE_COMPLETE = 10_557_600;
const toMs = microseconds => Math.round(microseconds / 1000);
const ELAPSED_MS = toMs(RESPONSE_COMPLETE - REQUEST_START);
const SERVING_MS = toMs(RESPONSE_COMPLETE - SERVING.resolving);
const STALL_MS = toMs(SERVING.resolving - REQUEST_START);
const SLACK_MS = 100;
const TIMING_KEYS = [
"blocked",
"dns",
"connect",
"ssl",
"send",
"wait",
"receive",
];
// What NetworkObserver records: `first` written once, `last` overwritten, so the
// two attempts are indistinguishable.
const TWO_ATTEMPT_TIMINGS = {
REQUEST_HEADER: { first: REQUEST_START, last: REQUEST_START },
STATUS_RESOLVING: { first: FAILED.resolving, last: SERVING.resolving },
STATUS_RESOLVED: { first: FAILED.resolved, last: SERVING.resolved },
STATUS_CONNECTING_TO: { first: FAILED.connecting, last: SERVING.connecting },
STATUS_CONNECTED_TO: { first: FAILED.connected, last: SERVING.connected },
STATUS_TLS_STARTING: {
first: SERVING.tlsStarting,
last: SERVING.tlsStarting,
},
STATUS_TLS_ENDING: { first: SERVING.tlsEnding, last: SERVING.tlsEnding },
STATUS_SENDING_TO: { first: FAILED.sending, last: SERVING.sending },
RESPONSE_START: { first: RESPONSE_START, last: RESPONSE_START },
RESPONSE_COMPLETE: { first: RESPONSE_COMPLETE, last: RESPONSE_COMPLETE },
};
// One healthy attempt, for the control.
const ONE_ATTEMPT_TIMINGS = {
REQUEST_HEADER: { first: 0, last: 0 },
STATUS_RESOLVING: { first: 1000, last: 1000 },
STATUS_RESOLVED: { first: 2000, last: 2000 },
STATUS_CONNECTING_TO: { first: 2600, last: 2600 },
STATUS_CONNECTED_TO: { first: 83_600, last: 83_600 },
STATUS_TLS_STARTING: { first: 83_600, last: 83_600 },
STATUS_TLS_ENDING: { first: 174_600, last: 174_600 },
STATUS_SENDING_TO: { first: 174_600, last: 174_600 },
RESPONSE_START: { first: 365_600, last: 365_600 },
RESPONSE_COMPLETE: { first: 401_600, last: 401_600 },
};
// nsHttpTransaction::Restart clears mTimings, and for a retry onto a new
// connection BootstrapTimings refills it, so the channel describes the attempt
// that served the request.
const SERVING_TIMED_CHANNEL = {
asyncOpenTime: 1,
domainLookupStartTime: SERVING.resolving,
domainLookupEndTime: SERVING.resolved,
connectStartTime: SERVING.connecting,
tcpConnectEndTime: SERVING.connected,
secureConnectionStartTime: SERVING.tlsStarting,
connectEndTime: SERVING.tlsEnding,
requestStartTime: SERVING.sending,
responseStartTime: RESPONSE_START,
responseEndTime: RESPONSE_COMPLETE,
};
const ONE_ATTEMPT_TIMED_CHANNEL = {
asyncOpenTime: 1,
domainLookupStartTime: 1000,
domainLookupEndTime: 2000,
connectStartTime: 2600,
tcpConnectEndTime: 83_600,
secureConnectionStartTime: 83_600,
connectEndTime: 174_600,
requestStartTime: 174_600,
responseStartTime: 365_600,
responseEndTime: 401_600,
};
function makeChannel(timedChannelValues = {}) {
return {
QueryInterface: ChromeUtils.generateQI(["nsITimedChannel"]),
asyncOpenTime: 0,
requestStartTime: 0,
responseStartTime: 0,
responseEndTime: 0,
tcpConnectEndTime: 0,
connectStartTime: 0,
connectEndTime: 0,
secureConnectionStartTime: 0,
domainLookupStartTime: 0,
domainLookupEndTime: 0,
...timedChannelValues,
};
}
function extract(timings, timedChannelValues, activityValues = {}) {
const result = NetworkTimings.extractHarTimings({
fromCache: false,
channel: makeChannel(timedChannelValues),
timings,
...activityValues,
});
info(
`timings=${JSON.stringify(result.timings)} ` +
`offsets=${JSON.stringify(result.offsets)} total=${result.total}`
);
return result;
}
function sumPhases(harTimings) {
return TIMING_KEYS.reduce(
(sum, key) => (harTimings[key] > 0 ? sum + harTimings[key] : sum),
0
);
}
function assertTotalMatches(total, expectedMs) {
Assert.lessOrEqual(
Math.abs(total - expectedMs),
SLACK_MS,
`total (${total}) matches the real duration (${expectedMs}ms)`
);
}
// The waterfall draws each bar at offsets[key], so they have to advance with the
// phases they position and end within the total.
function assertOffsetsFitTotal(offsets, timings, total) {
TIMING_KEYS.reduce((prev, key) => {
Assert.lessOrEqual(
offsets[prev],
offsets[key],
`offsets.${prev} (${offsets[prev]}) <= offsets.${key} (${offsets[key]})`
);
return key;
});
Assert.lessOrEqual(
offsets.receive + timings.receive,
total,
"the last bar ends within the reported total"
);
}
add_task(async function test_phases_measure_the_serving_attempt() {
const { timings } = extract(TWO_ATTEMPT_TIMINGS, SERVING_TIMED_CHANNEL);
// No DNS query was sent on the wire; this is the serving attempt's cached
// resolve.
Assert.equal(
timings.dns,
toMs(SERVING.resolved - SERVING.resolving),
"dns measures the serving attempt"
);
Assert.equal(
timings.connect,
toMs(SERVING.connected - SERVING.connecting),
"connect measures the serving attempt"
);
Assert.equal(
timings.ssl,
toMs(SERVING.tlsEnding - SERVING.tlsStarting),
"ssl measures the serving attempt"
);
Assert.equal(timings.send, 0, "send measures the serving attempt");
});
add_task(async function test_no_phase_exceeds_the_serving_attempt() {
const { timings, total } = extract(
TWO_ATTEMPT_TIMINGS,
SERVING_TIMED_CHANNEL
);
for (const key of TIMING_KEYS.filter(k => k !== "blocked")) {
Assert.lessOrEqual(
timings[key],
SERVING_MS + SLACK_MS,
`${key} (${timings[key]}) fits inside the serving attempt (${SERVING_MS}ms)`
);
}
// The stall is real and has to be reported somewhere.
Assert.lessOrEqual(
Math.abs(timings.blocked - STALL_MS),
SLACK_MS,
`blocked (${timings.blocked}) accounts for the stall (${STALL_MS}ms)`
);
// Two-sided: dropping the inflation without crediting blocked would leave the
// total too small, which is equally wrong.
assertTotalMatches(total, ELAPSED_MS);
});
add_task(async function test_phase_sum_never_exceeds_elapsed() {
// har-builder.js sums every phase for entry.time.
const { timings } = extract(TWO_ATTEMPT_TIMINGS, SERVING_TIMED_CHANNEL);
const sum = sumPhases(timings);
Assert.lessOrEqual(
sum,
ELAPSED_MS + SLACK_MS,
`phases (${sum}) do not sum past the real duration (${ELAPSED_MS}ms)`
);
});
add_task(async function test_offsets_monotonic() {
const { offsets, timings, total } = extract(
TWO_ATTEMPT_TIMINGS,
SERVING_TIMED_CHANNEL
);
assertOffsetsFitTotal(offsets, timings, total);
});
add_task(async function test_restart_onto_pooled_connection() {
// The conn mgr can re-dispatch onto an established connection, which resolves
// and connects nothing: Activate only bootstraps a connection's first
// transaction, so the channel has only its own requestStart. The failed
// attempt's STATUS_SENDING_TO is still there.
const { offsets, timings, total } = extract(TWO_ATTEMPT_TIMINGS, {
asyncOpenTime: 1,
requestStartTime: SERVING.sending,
responseStartTime: RESPONSE_START,
responseEndTime: RESPONSE_COMPLETE,
});
Assert.equal(timings.send, 0, "send measures the serving attempt");
// The absent phases must not walk the bars backwards.
assertOffsetsFitTotal(offsets, timings, total);
Assert.lessOrEqual(
Math.abs(timings.blocked - toMs(SERVING.sending)),
SLACK_MS,
`blocked (${timings.blocked}) accounts for the wait for a connection`
);
assertTotalMatches(total, ELAPSED_MS);
});
add_task(async function test_restart_after_a_response_was_parsed() {
// A 425, a 421 or an HTTP/2 to HTTP/1 fallback restarts after the response
// head was parsed, so RESPONSE_START belongs to the attempt that failed and is
// never reported again. Pairing it with the serving attempt would spread
// `receive` across the whole gap, and count it a second time after `blocked`
// already covers it.
const { timings, total } = extract(
{
...TWO_ATTEMPT_TIMINGS,
RESPONSE_START: { first: FAILED.sending + 1000, last: RESPONSE_START },
},
SERVING_TIMED_CHANNEL
);
Assert.lessOrEqual(
timings.receive,
SERVING_MS + SLACK_MS,
`receive (${timings.receive}) fits inside the serving attempt`
);
Assert.greaterOrEqual(timings.wait, 0, "wait is not left negative");
assertTotalMatches(total, ELAPSED_MS);
});
add_task(async function test_multi_write_send_is_measured() {
// A body split over several writes reports a genuinely long send. The clamp
// must not flatten it.
const sends = [174_600, 400_000, 674_600];
const complete = 901_600;
const { offsets, timings, total } = extract(
{
...ONE_ATTEMPT_TIMINGS,
STATUS_SENDING_TO: { first: sends[0], last: sends.at(-1) },
RESPONSE_START: { first: 865_600, last: 865_600 },
RESPONSE_COMPLETE: { first: complete, last: complete },
},
{
...ONE_ATTEMPT_TIMED_CHANNEL,
responseStartTime: 865_600,
responseEndTime: complete,
}
);
Assert.equal(
timings.send,
toMs(sends.at(-1) - sends[0]),
"a multi-write send spans the first write to the last"
);
// The offset has to be where sending began, not where it finished, or the bar
// is drawn past the end of the response and the duration is counted twice.
assertTotalMatches(total, toMs(complete));
assertOffsetsFitTotal(offsets, timings, total);
});
add_task(async function test_zero_rtt_send_is_measured() {
// With accepted 0-RTT the request goes out before the handshake finishes, and
// Apply0RTTTimingOverride moves connectEnd to that send point. The clamp must
// leave such a send alone.
const earlyData = 90_000;
const { timings } = extract(
{
...ONE_ATTEMPT_TIMINGS,
STATUS_SENDING_TO: { first: earlyData, last: 140_000 },
},
{
...ONE_ATTEMPT_TIMED_CHANNEL,
connectEndTime: earlyData,
requestStartTime: earlyData,
}
);
Assert.equal(
timings.send,
toMs(140_000 - earlyData),
"an accepted 0-RTT send is measured from the early data"
);
// The channel's connectEnd is rewritten to the early data send point here, so
// the handshake has to keep coming from the statuses.
Assert.equal(
timings.ssl,
toMs(174_600 - 83_600),
"the handshake is measured in full despite the 0-RTT connectEnd"
);
});
function withoutTlsStatuses() {
const timings = { ...ONE_ATTEMPT_TIMINGS };
delete timings.STATUS_TLS_STARTING;
delete timings.STATUS_TLS_ENDING;
return timings;
}
add_task(async function test_handshake_measures_the_serving_attempt() {
// Both attempts ran a handshake and reported it, so STATUS_TLS_STARTING.first
// is the failed attempt's while STATUS_TLS_ENDING.last is the serving one's.
// This is the variant behind HAR entries 5, 9, 11, 74 and 75, where the stall
// lands in ssl and connect stays short.
const { timings } = extract(
{
...TWO_ATTEMPT_TIMINGS,
STATUS_TLS_STARTING: {
first: FAILED.connected,
last: SERVING.tlsStarting,
},
},
SERVING_TIMED_CHANNEL
);
Assert.equal(
timings.ssl,
toMs(SERVING.tlsEnding - SERVING.tlsStarting),
"ssl measures the serving attempt's handshake"
);
Assert.lessOrEqual(
timings.ssl,
SERVING_MS + SLACK_MS,
`ssl (${timings.ssl}) fits inside the serving attempt (${SERVING_MS}ms)`
);
});
add_task(async function test_handshake_without_tls_statuses() {
// Happy Eyeballs runs the handshake against a null transaction, so neither TLS
// status reaches the channel. The channel recorded it regardless.
const { timings } = extract(withoutTlsStatuses(), ONE_ATTEMPT_TIMED_CHANNEL);
Assert.equal(
timings.ssl,
toMs(
ONE_ATTEMPT_TIMED_CHANNEL.connectEndTime -
ONE_ATTEMPT_TIMED_CHANNEL.secureConnectionStartTime
),
"the handshake is reported from the channel's own timings"
);
});
add_task(async function test_plain_http_connect_is_reported() {
// A plain HTTP request never stamps secureConnectionStart. Its connect still
// has to come from the channel, and no handshake may be invented for it.
const { timings } = extract(withoutTlsStatuses(), {
...ONE_ATTEMPT_TIMED_CHANNEL,
secureConnectionStartTime: 0,
});
Assert.equal(
timings.connect,
toMs(
ONE_ATTEMPT_TIMED_CHANNEL.tcpConnectEndTime -
ONE_ATTEMPT_TIMED_CHANNEL.connectStartTime
),
"connect is reported for a request with no handshake"
);
Assert.lessOrEqual(timings.ssl, 0, "no handshake is invented");
});
add_task(async function test_http3_connect_not_reported_twice() {
// For HTTP/3 secureConnectionStart is stamped when connecting starts, and no
// TLS statuses reach the channel. Taking it would report the whole connect a
// second time as ssl.
const { timings } = extract(withoutTlsStatuses(), {
...ONE_ATTEMPT_TIMED_CHANNEL,
secureConnectionStartTime: ONE_ATTEMPT_TIMED_CHANNEL.connectStartTime,
});
Assert.lessOrEqual(timings.ssl, 0, "no handshake is invented for HTTP/3");
});
add_task(async function test_single_attempt_unchanged() {
// Control: one attempt, where the statuses and the channel agree.
const { timings, total } = extract(
ONE_ATTEMPT_TIMINGS,
ONE_ATTEMPT_TIMED_CHANNEL
);
Assert.deepEqual(
timings,
{
blocked: 1,
dns: 1,
connect: 81,
ssl: 91,
send: 0,
wait: 191,
receive: 36,
},
"a single-attempt request keeps its phase durations"
);
assertTotalMatches(total, toMs(401_600));
});
// Throttling is simulated in NetworkObserver, which holds the response
// activities back and redispatches them with delayed timestamps. The channel
// records the transfer that really happened, so the response phases have to
// follow the activities or a throttled request is reported at full speed.
add_task(async function test_download_throttling_uses_the_activities() {
const delayed = {
...ONE_ATTEMPT_TIMINGS,
RESPONSE_COMPLETE: { first: 2_365_600, last: 2_365_600 },
};
const { timings: unthrottled } = extract(delayed, ONE_ATTEMPT_TIMED_CHANNEL);
Assert.equal(
unthrottled.receive,
36,
"without throttling the channel's own record is preferred"
);
const { timings } = extract(delayed, ONE_ATTEMPT_TIMED_CHANNEL, {
downloadThrottle: {},
});
Assert.equal(
timings.receive,
2000,
"a throttled transfer is measured from the delayed activities"
);
});
add_task(async function test_throttled_restart_measures_the_serving_attempt() {
// Throttling and a restart past the response head at once: the delayed
// RESPONSE_START belongs to the attempt that failed, so pairing it with the
// delayed RESPONSE_COMPLETE would spread `receive` over the whole stall that
// `blocked` already covers.
const { timings, total } = extract(
{
...TWO_ATTEMPT_TIMINGS,
RESPONSE_START: { first: FAILED.sending + 1000, last: RESPONSE_START },
},
SERVING_TIMED_CHANNEL,
{ downloadThrottle: {} }
);
Assert.lessOrEqual(
timings.receive,
SERVING_MS + SLACK_MS,
`receive (${timings.receive}) fits inside the serving attempt`
);
Assert.greaterOrEqual(timings.wait, 0, "wait is not left negative");
assertTotalMatches(total, ELAPSED_MS);
});