BandwidthObserved higher than BandwidthBurst

[keb]

got this line looking at my relay:
Bandwidth (Max/Burst/Observed - In Bps): 340992 / 1022976 / 30676070
1h20 after an upgrading from 0.2.2.22-alpha to 0.2.2.23-alpha

[keb]

state file from tor data dir

[arma]

Sure enough, BWHistoryWriteMaxima has values like 30689280. Are we writing them wrong, or using them wrong?

[nickm]

Roger suspects that the new remember-your-observed-bandwidth stuff in rephist.c in 0.2.2.23-alpha may be implicated.

[nickm]

The functions to scrutinize are rep_hist_update_bwhist_state_section, and rep_hist_load_bwhist_state_section , both in rephist.c .

[keb]

i should mention the 1st report line above is from
​http://torstatus.all.de/router_detail.php?FP=D3ED911183DF31FDB744A22F94BE6A856AC77D12
but when i got some output from blutmagie's status page a few hours later, it looks ok
​http://torstatus.blutmagie.de/router_detail.php?FP=d3ed911183df31fdb744a22f94be6a856ac77d12

so it is a case of one website misinterpreting the units in which that field is stored in the database?

[arma]

    maxval = b->maxima[i] / NUM_SECS_ROLLING_MEASURE;

implies that maxval is a per-second amount, whereas b->maxima is a per-10-second amount. So the Maxima we write to the state file is a per-second amount.

Then when we read it, we

       v = tor_parse_uint64(cp, 10, 0, UINT64_MAX, &ok, NULL);
        if (have_maxima) {
          maxstr = smartlist_get(s_maxima, cp_sl_idx);
          mv = tor_parse_uint64(maxstr, 10, 0, UINT64_MAX, &ok_m, NULL);
          mv *= NUM_SECS_ROLLING_MEASURE;
        } else {
          /* No maxima known; guess average rate to be conservative. */
          mv = v / s_interval;
        }

and then

          b->max_total = mv;

where max_total is also a per-10-second amount. So

          mv = v / s_interval;

ought to be

          mv = v / s_internal * NUM_SECS_ROLLING_MEASURE;

But that's not our bug, since it would produce smaller numbers not larger numbers. But it is a bug.

[arma]

Also, why is the argument for rep_hist_load_bwhist_state_section() called s_begins yet the state line is called "BWHistoryWriteEnds"? That sounds like a recipe for more confusion.

[arma]

This could be it:

          add_obs(b, start, v);

We are reading in a per-900-second value, and then telling our rephist system that at second 'start', we saw all of those bytes get written. I suspect this causes the per-10-second calculation to be 1/10 of the per-900-second value.

[arma]

moria1 has funny-looking values here too:

BWHistoryReadValues 536190976,409089024,532183040,497468416,...
BWHistoryReadMaxima 53618688,40908800,53218304,49745920,...

Notice the pattern?

[keb]

(The following redundant note is added to catch user searches.)
Vidalia "Tor Bandwidth Usage" chart is affected by this issue. The vertical scale is much larger than the actual transfer numbers, so the indicator hardly leaves the floor.

[arma]

One way to resolve this one for 0.2.2 is to revert the patch that caused it.

Then we could reschedule that patch for 0.2.3, but not merge it in yet because of this bug.

[mikeperry]

Hrmm, I hope we're not using int32_t's anywhere related to this. We're approaching maxint observed bandwidth on several relays. I guess we'll find out how robust all associated tor and non-tor code is soon :).

[Sebastian]

I think part of the analysis here is wrong. Specifically, the suggestion to do

          mv = v / s_internal * NUM_SECS_ROLLING_MEASURE;

is good, but doesn't influence the other bug this ticket is about, because the above fix is only relevant when we don't know the maximum. If we know the maximum, we already do

          mv *= NUM_SECS_ROLLING_MEASURE;

[Sebastian]

Oh, also I think we should not just revert the patch. I have a fix that seems to work in local testing, cleaning it up to add it here.

[Sebastian]

bug2704 in my repository

[nickm]

We ran into a bug on IRC:

18:56 < nickm> hang on. That loop, where we do "while (start < now)". Is that

right? If this interval is not the most recent one, then won't
we add the observation far too many times?

and a simplification:

18:57 < nickm> also you can simplify the overflow logic a lot
18:57 < nickm> instead of overflow, have, say, "actual_interval_len". Set it

to either s_interval or to now-start.

18:57 < nickm> then compute cur = v / actual_interval_len

[Sebastian]

pushed an update. tested in private network again. Thanks!

[nickm]

Thanks! Rebased (for the fixup) & merged.

[nickm]

Apparently arma says this isn't fixed for him on moria1, and that he's talked about it with sebastian. Somebody please post here?

[Sebastian]

moria1's current descriptor says bandwidth 512000 10485760 1306223, with the burst well within above the max observed.

Looking at the past days, moria reported very high values shortly after starting up, and the values then dropped. This didn't appear to change significantly with the patch vs without it.

[Sebastian]

I can't really reproduce the issue with fluxe3, however: I just restarted it (on 0.2.2.24-alpha), and in its descriptor it said bandwidth 921600 10240000 83463884 - so we don't have an inflated value here. hrm.

[Sebastian]

Eh, disregard the comment above. I guess my maths sucks a little more than usual today

[Sebastian]

Here's another bug in rep_hist_update_bwhist_state_section(), I think:

  tor_asprintf(&cp, U64_FORMAT, U64_PRINTF_ARG(b->max_total & ~0x3ff));
  smartlist_add(*s_maxima, cp);
}}
It seems we need to divide b->max_total by NUM_SECS_ROLLING_MEASURE, no?

Also, this following change from 105b94b7 seems to be strange to me, but I can't put my finger on why so far.
{{{
   /* Clean up maxima and observed */
-  /* Do we really want to zero this for the purpose of max capacity? */
   for (i=0; i<NUM_SECS_ROLLING_MEASURE; ++i) {
     b->obs[i] = 0;
   }
   b->total_obs = 0;
-  for (i=0; i<NUM_TOTALS; ++i) {
-    b->maxima[i] = 0;
-  }
-  b->max_total = 0;
}}}

[Sebastian]

ok, so I think we should definitely fix that bug soon. This does lead to inflated Maxima history in the state file. bug2704 for the patch.

[Sebastian]

thanks for the merge, and sorry for the silly compile error.

[arma]

I'm calling this one fixed. This time for sure! Thanks.