qlog
qlog copied to clipboard
Take a long hard look at QPACK events
At the moment, the QPACK events very closely mimic the QPACK instructions as defined in the draft (Or at least, they should... the current definitions are somewhat outdated wrt the final QPACK draft, mostly in terms of naming).
However, to my knowledge, not a single QPACK implementation has actually implemented qlog output. Additionally, the QPACK instructions are likely not the easiest to understand or use for debugging outside of the key QPACK implementers. Put differently: higher-level events (e.g., indicating when things were HOL blocked on QPACK, when SETTINGS_QPACK_BLOCKED_STREAMS
or SETTINGS_QPACK_MAX_TABLE_CAPACITY
are reached, when errors occur, when a header is added/removed to the dynamic table, etc.) might be more interesting overall.
This would however require someone with considerable QPACK experience to come in an help define these events, preferably in tandem with a QPACK/H3 implementation also outputting qlog events for this. CC @afrind
I think the kind of blocked events you are talking about are the most likely to be of general use, since one doesn't really need to be a QPACK expert to understand that latency at the HTTP layer is being introduced because of a QPACK dependency.
I can also imagine somewhat more detailed error information being useful when QPACK hits an error.
We had a jump in QPACK errors last year that required a significant bit of debugging (and as you note, we don't have QPACK QLOG events). I'm trying to recall the debugging steps and I think it might have been helpful to have every QPACK instruction logged at both the encoder and decoder. To exonerate QPACK in this instance, the issue turned out to be transport related. However, this is likely to be produce a lot of data that is not generally useful, and can be especially sensitive for PII reasons compared to generic QLOG transport data. So I can see implementations not using this detailed mode all the time or by default.
A proposal for QPACK events -- @afrind
The current QLOG events for QPACK focus on 3 main event types:
Header block encoded/decoded, state updates, and raw instructions.
The most common reasons to examine QPACK interactions in detail are to investigate correctness or performance issues. This is a proposal for a restructuring of the QPACK events to represent higher level conditions that would be most useful to that end, rather than a pure instruction-by-instruction log.
We also propose an event with a summary of QPACK stats for the whole connection.
Encoder Events:
-
Encoded a field section block:
[required] Application bytes [required] Compressed bytes sent In this block On the encoder stream, directly attributable to this block [required] Number of field lines in the block [required] Blocking Risk (bool) – (references an unacknowledged dynamic table entry) Number of dynamic table inserts triggered by encoding this block Number of Static table references (names & values) Number of Static table name references with literal values Number of Dynamic table references (names & values) Number of Dynamic table name references with literal values Number of entries with literal names and values Number of application bytes sent as literals Number of bytes sent as huffman literals (To compute compression ratio from huffman) Minimum dynamic table reference Maximum dynamic table reference
-
Blocked Insertion: Wanted to insert an entry into the dynamic table, but eviction was blocked due to unacknowledged references
-
Avoided Reference: Wanted to reference an older entry in the dynamic table but chose not to because doing so might result in blocking future evictions
-
Blocked Reference: Wanted to reference the dynamic table but reached max blocking
-
Encoder Stream Flow Control Blocked: Ran out of Encoder Stream flow control
Decoder Events:
-
Decoded a field section block:
[required] Application bytes [required] Compressed bytes received in this block [required] Number of field lines in this block Number of dynamic table inserts triggered by encoding this block Number of Static table references (names & values) Number of Static table name references with literal values Number of Dynamic table references (names & values) Number of Dynamic table name references with literal values Number of entries with literal names and values Number of application bytes sent as literals Number of bytes sent as huffman literals (To compute compression ratio from huffman) Queue time (how long blocked waiting for dynamic table)
-
Decoding Blocked: Received block that could not be decoded because it depends on dynamic table entries that have not arrived
-
Insert Count Increment: - indicates delayed block arrival or processing, or speculative inserts
Connection End Event (summary):
Should have an encoder and decoder section
Total application header bytes
Total compressed header bytes sent or received (including encoder/decoder bytes)
Num Static table name/value references
Static table name references
Dynamic table name/value references
Dynamic table name references
Num insertions
Num evictions
Num duplications
[optional] QPACK Connection Error Detail
[encoder only] Num blocked insertions
[decoder only] Num queued decodes
[decoder only] Total queued decode latency
[decoder only] Num QPACK Stream Errors
Dumb question 1 - can these events be generalised to cover HPACK and QPACK? I think the blocking bits probably mean no but figured I'd ask.
Dumb question 2 - what does Num QPACK Stream Errors
mean? Isn't a single error a terminal problem for the connection, or can there be more than one?
We looked hard and decided to remove them and let someone else do the work in a separate draft. Closing this now.