[tor-bugs] #17598 [- Select a component]: Trace cell queue times in Tor to measure Tor application "congestion"

[Tor Bug Tracker & Wiki]

#17598: Trace cell queue times in Tor to measure Tor application "congestion"
----------------------------------+---------------------
 Reporter:  robgjansen            |          Owner:
     Type:  enhancement           |         Status:  new
 Priority:  Medium                |      Milestone:
Component:  - Select a component  |        Version:
 Severity:  Normal                |     Resolution:
 Keywords:                        |  Actual Points:
Parent ID:  #12541                |         Points:
  Sponsor:                        |
----------------------------------+---------------------

Comment (by robgjansen):

 Here are my notes about the instrumentation we need to properly test KIST:

 **What to record**

   1. read from kernel input buffer into a cell struct

 `connection_or_process_cells_from_inbuf()`

 Either a `cell_t` or a `var_cell_t` get created in this func. This is
 where we can set the unique id and add a call site.

   2. change cell into a packed_cell

 `connection_or_write_cell_to_buf()`
 `connection_or_write_var_cell_to_buf()`

 Here the `cell_t` or `var_cell_t` gets "packed" into a `packed_cell_t`
 that can be written onto the network. The callsite is after the cell is
 packed but before it is written with `connection_write_to_buf()`.

   3. write network bytes from tor output buffer to kernel output buffer

 In 2 above, the cell gets written to _Tor_ output buffer in
 `connection_write_to_buf()`, and now we want to add a callsite when that
 cell gets written from Tor to the _kernel_.

 Since the _tor_ output buffer is just a buffer of raw bytes, we won't
 actually know when that cell gets written since we have no struct
 information. So we use a heuristic of counting bytes to guess instead.

 After writing e.g. cell 123 in `connection_write_to_buf()`, check the
 length of the output buffer for that connection. Lets say the length is
 2048 (4 cells). Now we know that cell 123 is in the 4th position, i.e. at
 buf[1536:2048]. A soon as that connection flushes the 2048th byte from the
 buffer, we know that cell 123 will have been completely transferred to the
 kernel.

 We need to keep state in the meantime, keeping track of:
  - cell 123
  - conn XXX
  - bytes_remaining 2048

 Then every time that connection XXX flushes some data, subtract the
 bytes_remaining counter. When the bytes_remaining counter is <=0, then
 call the final call site to log the "kernel write" event, and delete the
 state for cell 123.

 Connection bytes written get reported in `connection_buckets_decrement()`.
 I think the bytes reported there might include the TLS overhead, so you
 need to make sure to subtract off that overhead to make sure the counter
 lines up correctly with bytes stored in the tor connection buffer.

 **Output format**

 Let's start by writing with Tor's log interface. If we could configure a
 log level at build time that would be helpful, otherwise log_notice.

 Format is something like "<timestamp> <cellid>" and of course the event
 name will be needed also.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/17598#comment:1>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online