diff --git a/doc/spec/control-spec.txt b/doc/spec/control-spec.txt index b60baba052..1938fa226c 100644 --- a/doc/spec/control-spec.txt +++ b/doc/spec/control-spec.txt @@ -1670,13 +1670,14 @@ The syntax is: "650" SP "BUILDTIMEOUT_SET" SP Type SP "TOTAL_TIMES=" Total SP "TIMEOUT_MS=" Timeout SP "XM=" Xm SP "ALPHA=" Alpha SP - "CUTOFF_QUANTILE=" Quantile CRLF + "CUTOFF_QUANTILE=" Quantile SP "TIMEOUT_RATE=" Rate CRLF Type = "COMPUTED" / "RESET" / "SUSPENDED" / "DISCARD" / "RESUME" Total = Integer count of timeouts stored Timeout = Integer timeout in milliseconds Xm = Estimated integer Pareto parameter Xm in milliseconds Alpha = Estimated floating point Paredo paremter alpha Quantile = Floating point CDF quantile cutoff point for this timeout + Rate = Floating point ratio of circuits that timeout A new circuit build timeout time has been set. If Type is "COMPUTED", Tor has computed the value based on historical data. If Type is "RESET", diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index ddc86191f0..b54952450a 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -306,8 +306,7 @@ circuit_build_times_add_time(circuit_build_times_t *cbt, build_time_t time) return -1; } - // XXX: Probably want to demote this to debug for the release. - log_info(LD_CIRC, "Adding circuit build time %u", time); + log_debug(LD_CIRC, "Adding circuit build time %u", time); cbt->circuit_build_times[cbt->build_times_idx] = time; cbt->build_times_idx = (cbt->build_times_idx + 1) % CBT_NCIRCUITS_TO_OBSERVE; @@ -733,9 +732,6 @@ void circuit_build_times_add_timeout_worker(circuit_build_times_t *cbt, double quantile_cutoff) { - // XXX: This may be failing when the number of samples is small? - // Keep getting values for the largest timeout bucket over and over - // again... Probably because alpha is very very large in that case.. build_time_t gentime = circuit_build_times_generate_sample(cbt, quantile_cutoff, CBT_MAX_SYNTHETIC_QUANTILE); @@ -988,6 +984,22 @@ circuit_build_times_network_check_changed(circuit_build_times_t *cbt) return 1; } +/** + * Count the number of timeouts in a set of cbt data. + */ +double +circuit_build_times_timeout_rate(const circuit_build_times_t *cbt) +{ + int i=0,timeouts=0; + for (i = 0; i < CBT_NCIRCUITS_TO_OBSERVE; i++) { + if (cbt->circuit_build_times[i] >= cbt->timeout_ms) { + timeouts++; + } + } + + return ((double)timeouts)/cbt->total_build_times; +} + /** * Store a timeout as a synthetic value. * @@ -1024,7 +1036,7 @@ circuit_build_times_add_timeout(circuit_build_times_t *cbt, circuit_build_times_count_pretimeouts(cbt); circuit_build_times_add_timeout_worker(cbt, - circuit_build_times_quantile_cutoff()); + circuit_build_times_quantile_cutoff()); return 1; } @@ -1033,7 +1045,8 @@ static int circuit_build_times_filter_timeouts(circuit_build_times_t *cbt) { int num_filtered=0, i=0; - build_time_t max_timeout; + double timeout_rate = 0; + build_time_t max_timeout = 0; /* If we replace high timeouts when the curve is really steep * (alpha is above ~1.5), we can end up with a lot of timeouts clustered @@ -1045,6 +1058,7 @@ circuit_build_times_filter_timeouts(circuit_build_times_t *cbt) return 0; } + timeout_rate = circuit_build_times_timeout_rate(cbt); max_timeout = tor_lround(circuit_build_times_calculate_timeout(cbt, CBT_MAX_SYNTHETIC_QUANTILE)); @@ -1054,15 +1068,21 @@ circuit_build_times_filter_timeouts(circuit_build_times_t *cbt) num_filtered++; cbt->circuit_build_times[i] = MIN(circuit_build_times_generate_sample(cbt, - circuit_build_times_quantile_cutoff(), - CBT_MAX_SYNTHETIC_QUANTILE), - CBT_BUILD_TIME_MAX); + circuit_build_times_quantile_cutoff(), + CBT_MAX_SYNTHETIC_QUANTILE), + CBT_BUILD_TIME_MAX); - log_info(LD_CIRC, "Replaced timeout %d with %d", replaced, + log_debug(LD_CIRC, "Replaced timeout %d with %d", replaced, cbt->circuit_build_times[i]); } } + log_info(LD_CIRC, + "We had %d timeouts out of %d build times, " + "and filtered %d above the max of %u", + (int)(cbt->total_build_times*timeout_rate), + cbt->total_build_times, num_filtered, max_timeout); + return num_filtered; } @@ -1094,13 +1114,12 @@ void circuit_build_times_set_timeout(circuit_build_times_t *cbt) { int filtered=0,timeouts=0,i=0; + double timeout_rate; if (!circuit_build_times_set_timeout_worker(cbt)) return; if ((filtered = circuit_build_times_filter_timeouts(cbt)) > 0) { - log_info(LD_CIRC, "Filtered out %d timeouts. Recomputing timeout.", - filtered); circuit_build_times_set_timeout_worker(cbt); } @@ -1112,11 +1131,7 @@ circuit_build_times_set_timeout(circuit_build_times_t *cbt) control_event_buildtimeout_set(cbt, BUILDTIMEOUT_SET_EVENT_COMPUTED); - for (i = 0; i < CBT_NCIRCUITS_TO_OBSERVE; i++) { - if (cbt->circuit_build_times[i] >= cbt->timeout_ms) { - timeouts++; - } - } + timeout_rate = circuit_build_times_timeout_rate(cbt); log_info(LD_CIRC, "Set circuit build timeout to %lds (%lfms, Xm: %d, a: %lf, r: " diff --git a/src/or/control.c b/src/or/control.c index 5797edfdce..b5cc6c7b6d 100644 --- a/src/or/control.c +++ b/src/or/control.c @@ -3529,10 +3529,12 @@ control_event_buildtimeout_set(const circuit_build_times_t *cbt, send_control_event(EVENT_BUILDTIMEOUT_SET, ALL_FORMATS, "650 BUILDTIMEOUT_SET %s TOTAL_TIMES=%lu " - "TIMEOUT_MS=%lu XM=%lu ALPHA=%lf CUTOFF_QUANTILE=%lf\r\n", + "TIMEOUT_MS=%lu XM=%lu ALPHA=%lf CUTOFF_QUANTILE=%lf " + "TIMEOUT_RATE=%lf\r\n", type_string, (unsigned long)cbt->total_build_times, (unsigned long)cbt->timeout_ms, - (unsigned long)cbt->Xm, cbt->alpha, qnt); + (unsigned long)cbt->Xm, cbt->alpha, qnt, + circuit_build_times_timeout_rate(cbt)); return 0; } diff --git a/src/or/or.h b/src/or/or.h index 7402f4a385..c4cafcb12a 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -3152,6 +3152,7 @@ int circuit_build_times_needs_circuits_now(circuit_build_times_t *cbt); void circuit_build_times_init(circuit_build_times_t *cbt); void circuit_build_times_new_consensus_params(circuit_build_times_t *cbt, networkstatus_t *ns); +double circuit_build_times_timeout_rate(const circuit_build_times_t *cbt); #ifdef CIRCUIT_PRIVATE double circuit_build_times_calculate_timeout(circuit_build_times_t *cbt,