Run client-side experiments on CBT to test timeout cutoff and two guard use

changed due date to October 31, 2020

changed milestone to %Sponsor 61 - Making the Tor network faster & more reliable for users in Internet-repressive places

added Performance Sponsor 61 - FINISHED Task labels

changed the description

mentioned in issue #40150 (closed)

added Next label

I just re-read the CBT code to check to see how trustworthy BUILDTIMEOUT_SET control port event values should be.

It turns out the TIMEOUT_RATE field in BUILDTIMEOUT_SET reports the number of circuits that actually did timeout. This means for the first 100 circuits prior to learning a timeout, those circuits won't be likely to timeout, but will still be counted in the stats. This will drive our TIMEOUT_RATE lower than what it will be after a timeout is learned.

When we learn a new timeout, LD_CIRC info level log lines are emitted, that retroactively compute what the timeout rate would be if that timeout had applied over all if the past 1000 circuit build times (rolling window). You can see these loglines in circuit_build_times_set_timeout(). circuit_build_times_timeout_rate() is the function that does this computation.

marked this issue as related to #40150 (closed)

Ok I took a look at vanguards's cbtverify. It also keeps all timeout stats. So it will count timeouts and circs while a buildtimeout is still being learned (esp after a DROPTIMEOUTS command). So that code needs some tuning to optionally ignore timeouts and circs in while no CBT exists.

For the onionperf side, https://gitlab.torproject.org/tpo/metrics/onionperf/-/issues/33420 and https://gitlab.torproject.org/tpo/metrics/onionperf/-/issues/33399 make me think onionperf measurements between timeout computation might not be removed from results yet either. One more thing to check.

changed the description

Ok a push to vanguards to ignore circuits between BUILDTIMEOUT_SET RESET and BUILDTIMEOUT_SET COMPUTED is here: https://github.com/mikeperry-tor/vanguards/commit/77456dc4644b1f64f46c2b7ab33818e5825a4a3f

Note that vanguards assumes that when it is attached, the CBT timeout is already computed. If this is not true, it will also record those first 100 build times before the timeout is applied. This will bias its statistics until the first time the timeout is computed. This means the very first onionperf run will have wrong numbers from both BUILDTIMEOUT_SET and vanguards cbtverify. But after the first guard change or timeout computation, things will work properly in vanguards.

vanguards --enable_cbtverify --disable_vanguards will still count both general purpose and onion circ timeout rates.

After running over the weekend with 0b413f81 and a 60% cutoff, plus vanguards with cbtverify on, here are the last logs of vanguards:

INFO[Mon Nov 09 10:51:54 2020]: CBT Timeout rate: 0.380823; Our measured timeout rate: 0.3815179606025492; Hidden service timeout rate: 0.0
INFO[Mon Nov 09 10:51:54 2020]: 650 BUILDTIMEOUT_SET COMPUTED TOTAL_TIMES=1000 TIMEOUT_MS=307 XM=214 ALPHA=2.521902 CUTOFF_QUANTILE=0.600000 TIMEOUT_RATE=0.380823 CLOSE_MS=60000 CLOSE_RATE=0.030509
INFO[Mon Nov 09 10:51:55 2020]: CBT Timeout rate: 0.380823; Our measured timeout rate: 0.38146270818247646; Hidden service timeout rate: 0.0
INFO[Mon Nov 09 10:51:55 2020]: 650 BUILDTIMEOUT_SET COMPUTED TOTAL_TIMES=1000 TIMEOUT_MS=307 XM=214 ALPHA=2.524826 CUTOFF_QUANTILE=0.600000 TIMEOUT_RATE=0.380823 CLOSE_MS=60000 CLOSE_RATE=0.030509
INFO[Mon Nov 09 10:52:54 2020]: CBT Timeout rate: 0.380771; Our measured timeout rate: 0.3814074717636838; Hidden service timeout rate: 0.0
INFO[Mon Nov 09 10:52:54 2020]: 650 BUILDTIMEOUT_SET COMPUTED TOTAL_TIMES=1000 TIMEOUT_MS=307 XM=214 ALPHA=2.527752 CUTOFF_QUANTILE=0.600000 TIMEOUT_RATE=0.380771 CLOSE_MS=60000 CLOSE_RATE=0.030505
NFO[Mon Nov 09 10:53:54 2020]: CBT Timeout rate: 0.380719; Our measured timeout rate: 0.38135225133922107; Hidden service timeout rate: 0.0
INFO[Mon Nov 09 10:53:54 2020]: 650 BUILDTIMEOUT_SET COMPUTED TOTAL_TIMES=1000 TIMEOUT_MS=307 XM=214 ALPHA=2.532941 CUTOFF_QUANTILE=0.600000 TIMEOUT_RATE=0.380719 CLOSE_MS=60000 CLOSE_RATE=0.030501

This seems pretty accurate to me, so I guess it means that BUILDTIMEOUT_SET does report the right timeout value.

Should we also cross that item off the top list?

assigned to @asn and unassigned @dgoulet

assigned to @dgoulet and unassigned @asn

assigned to @asn and unassigned @dgoulet

added Doing label and removed Next label

marked the checklist item Run guard-based onionperf instances with two guards as completed

marked the checklist item Ensure onionperf is properly using two guards as completed

OK so an update here. I've been running onionperf as follows: $ onionperf measure -i --tgen ~/tgen/build/src/tgen --tor ~/onionperf/tor/src/app/tor --drop-guards 4 --additional-client-conf "NumEntryGuards 3"

I have validated that Tor will use 3 guards by monitoring its logs and making sure it doesn't stray out of the 3 top guards.

We have managed to reproduce an abnormally small CBT timeout rate as also observed by Karsten: https://gitlab.torproject.org/tpo/metrics/onionperf/-/issues/33420#note_2706400

My next step in debugging this (after talking with Mike) is running Onionperf for some time (also using the --drop-guards command) and then graph the build timeout histograms on top of a Pareto curve to see if those timeouts actually fit the curve or not.

added S61-O1-Maybe - FINISHED label

Run client-side experiments on CBT to test timeout cutoff and two guard use

Child items ...

Activity