Opened 5 years ago

Closed 3 years ago

#17598 closed enhancement (wontfix)

Trace cell queue times in Tor to measure Tor application "congestion"

Reported by: robgjansen Owned by: pastly
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: kist
Cc: Actual Points:
Parent ID: #12541 Points: 4
Reviewer: Sponsor: SponsorQ-can


In order to do #12892, we need to be able to measure congestion in the kernel and congestion in Tor. For the kernel, we can use libkqtime:

This ticket is to add the components needed to compute Tor congestion, as part of dgoulet's new instrumentation framework.

Child Tickets

Change History (20)

comment:1 Changed 5 years ago 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


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.

  1. change cell into a packed_cell


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().

  1. 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.

comment:2 Changed 5 years ago by nickm

Component: - Select a componentTor
Milestone: Tor: 0.2.8.x-final

comment:3 Changed 5 years ago by dgoulet

So I want to fully understand here. The goal is:

1) Record when a cell is created with the amount of bytes

--> Keep in state the cell ID and size for a specific connection X.

2) Record the amount of bytes once it's packed (??)

--> Update the state with the packed size for the cell ID and connection X.
--> Record the position of the packed cell in the output buf just after we wrote in it.

3) Record when that specific cell is written to the kernel

--> For connection X, record when the cell ID has been written to the kernel.

Is that correct?

comment:4 in reply to:  3 Changed 5 years ago by robgjansen

Replying to dgoulet:

Is that correct?

Pretty much, though I don't think you need the cell size. You just need the position in the Tor outbuf in order to compute when the cell gets written to the kernel.

The flow will be like this:

  1. Read bytes from kernel input socket to Tor incoming connection X buffer
  2. Turn bytes from Tor incoming connection X buffer into a cell C
  3. LOG: Record 'socket_read' event for Cell C ID and timestamp
  4. Cell C gets processed
  5. Cell C gets packed for next hop
  6. Cell C gets written to Tor output connection Y buffer
  7. STATE: Store Cell C ID and its position in the Tor output connection Y buffer in memory
  8. STATE: Update buffer position of Cell C whenever output connection Y writes more bytes to kernel output socket
  9. LOG: when position indicates Cell C is now in the kernel, record 'socket_write' event for Cell ID and timestamp
  10. STATE: Clear state for Cell C

Does that help?

Last edited 5 years ago by robgjansen (previous) (diff)

comment:5 Changed 5 years ago by nickm

Milestone: Tor: 0.2.8.x-finalTor: 0.2.9.x-final

These seem like features, or like other stuff unlikely to be possible this month. Bumping them to 0.2.9

comment:6 Changed 5 years ago by nickm

Points: medium/large

comment:7 Changed 4 years ago by dgoulet

Cc: dgoulet removed
Keywords: kist added
Milestone: Tor: 0.2.9.x-finalTor: 0.2.???
Points: medium/large4

This is linked to #13802 that is the need for an instrumentation framework so this cell measurement can use it. I already have some code prepared for this in branch ticket13802_028_01. Not working yet but at least a good start.

comment:8 Changed 4 years ago by pastly

Updated #13802 with this already.

Public branch with working shadow traces as we need them today is here.

comment:9 Changed 4 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:10 Changed 4 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:11 Changed 4 years ago by pastly

Owner: set to pastly
Status: newassigned

New public branch. Ready for review.

comment:12 Changed 4 years ago by pastly

Status: assignedneeds_review

comment:13 Changed 4 years ago by robgjansen

David's tracing branch is great, and I think it will be extremely useful for a variety of research and testing purposes. We have already implemented and are using a feature that uses the tracing branch to measure congestion times of cells in Tor.

If there are concerns about merging such individual "tracing modules" like this, I'd like to offer some reasons why I think it is a good idea to merge. Here are some advantages to merging tracepoint modules, in this case specifically our cell tracing module:

  • make sure the tracepoints are in the correct spot - future researchers/devs that want to measure congestion don't have to make the mistakes we first made about where to place the tracepoints
  • very few lines of code added to Tor for cell tracing (just a few tracepoints and a cell id) - most logic is in the cell tracing module
  • the cell tracing feature doesn't get compiled in unless manually setting a configure option
  • the cell tracing module is self contained and private and therefore not vulnerable to code rot, the only code that needs to be maintained are the tracepoint locations, which are indeed valuable to maintain by those who know the codebase and not by researchers/devs who want cell congestion data but are not Tor code experts
  • currently, our cell congestion tracing implementation minimizes the lines of code changed in Tor, but we could instead opt to provide more fine grained tracepoints - we could trace cell queue times in all of the inbuf and outbuf queues separately - more data could mean more useful to more researchers

comment:14 Changed 4 years ago by teor

Milestone: Tor: unspecifiedTor: 0.3.1.x-final

Assigning this to 0.3.1 because it has an implementation that's ready for review, and 0.3.1 is the next release. (0.3.0 was frozen a few weeks ago.)

robgjansen, pastly: a hint about how we use trac: tickets that aren't in a milestone (or that are in an outdated or far future milestone) don't get looked at.

comment:15 Changed 4 years ago by pastly

Status: needs_reviewneeds_revision

Needs revision.

Log lines like the following are wrong and likely the source of problems I had many many months ago.

"%lu.%lu id=%" PRIu32, cell->ts.tv_sec, cell->ts.tv_nsec, cell->id

This would print a timestamp of 1.9 seconds when we're actually 1.000000009 seconds.

There's also an incrementing dummy variable that needs to go away.

comment:16 Changed 3 years ago by pastly

Milestone: Tor: 0.3.1.x-finalTor: 0.3.2.x-final

This will not make it into 031. In addition to the above bug, it does not trace cells that originate at an exit (and I suspect cells that originate at the OP).

It only traces cells that come in from connection_or_process_cells_from_inbuf. It probably should trace cells that are created in relay_send_command_from_edge_ too.

This is a big deal for our needs.

Maybe tracing cells that don't go through the inbuf and start already halfway through Tor is different enough that they should be logged differently. For us right now, I don't think the difference is important and we really want the data from the additional cells.

comment:17 Changed 3 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:18 Changed 3 years ago by nickm

Sponsor: SponsorQ-can

comment:19 Changed 3 years ago by dgoulet

Milestone: Tor: 0.3.2.x-finalTor: unspecified

comment:20 in reply to:  11 Changed 3 years ago by pastly

Resolution: wontfix
Status: needs_revisionclosed

Replying to pastly:

New public branch. Ready for review.

Rebasing this to use the revised event logging system that is now in Tor would take time and we don't need it any more. We're done testing kist at this level (for now?).

Note: See TracTickets for help on using tickets.