qlog icon indicating copy to clipboard operation
qlog copied to clipboard

Take a long hard look at QPACK events

Open rmarx opened this issue 2 years ago • 1 comments

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

rmarx avatar Mar 20 '22 15:03 rmarx

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.

afrind avatar Mar 21 '22 09:03 afrind

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

lnicco avatar Mar 26 '23 20:03 lnicco

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?

LPardue avatar Mar 27 '23 02:03 LPardue

We looked hard and decided to remove them and let someone else do the work in a separate draft. Closing this now.

LPardue avatar Dec 09 '23 21:12 LPardue