[tor-bugs] #2004 [- Select a component]: Capping descriptor build times notice log

Mon Oct 4 17:48:30 UTC 2010

#2004: Capping descriptor build times notice log
----------------------------------+-----------------------------------------
 Reporter:  Sebastian             |       Owner:     
     Type:  defect                |      Status:  new
 Priority:  normal                |   Milestone:     
Component:  - Select a component  |     Version:     
 Keywords:                        |      Parent:     
----------------------------------+-----------------------------------------
Description changed by Sebastian:

Old description:

> Recently we introduced a maximum circuit build time of twice what we ever
> observed, but when we do cap we emit a notice log, which can be quite
> spammy. We should not have all these cbt notice logs, I think - they
> don't really tell the user anything, they aren't necessarily an
> indication of a problem, etc.
>
> Also, there seems to be a bug:
>
> [[[
>
> Oct 04 19:38:05.311 [notice] Circuit build measurement period of 118361ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:38:05.311 [notice] Based on 162 circuit times, it looks like we
> don't need to wait so long for circuits to finish. We will now assume a
> circuit is too slow to use after waiting 10 seconds.
> Oct 04 19:38:10.075 [notice] Circuit build measurement period of 117281ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
>
> Oct 04 19:38:12.271 [notice] Circuit build measurement period of 117330ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:38:16.805 [notice] Circuit build measurement period of 120054ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:38:21.109 [notice] Circuit build measurement period of 117447ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:38:38.345 [notice] Circuit build measurement period of 122752ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:41:05.013 [notice] Circuit build measurement period of 135039ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:42:06.013 [notice] Circuit build measurement period of 148555ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:42:06.013 [notice] Based on 169 circuit times, it looks like we
> need to wait longer for circuits to finish. We will now assume a circuit
> is too slow to use after waiting 11 seconds.
> Oct 04 19:44:08.013 [notice] Circuit build measurement period of 163425ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:45:09.013 [notice] Circuit build measurement period of 179783ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:45:09.013 [notice] Based on 171 circuit times, it looks like we
> need to wait longer for circuits to finish. We will now assume a circuit
> is too slow to use after waiting 12 seconds.
> Oct 04 19:46:10.013 [notice] Circuit build measurement period of 197779ms
> is more than twice the maximum build time we have ever observed. Capping
> it to 116950ms.
> Oct 04 19:46:10.013 [notice] Based on 172 circuit times, it looks like we
> need to wait longer for circuits to finish. We will now assume a circuit
> is too slow to use after waiting 13 seconds.
> }}}
>
> We never increase the value we're capping to, instead of doubling it.

New description:

 Recently we introduced a maximum circuit build time of twice what we ever
 observed, but when we do cap we emit a notice log, which can be quite
 spammy. We should not have all these cbt notice logs, I think - they don't
 really tell the user anything, they aren't necessarily an indication of a
 problem, etc.

 Also, there seems to be a bug:

 {{{
 Oct 04 19:38:05.311 [notice] Circuit build measurement period of 118361ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:38:05.311 [notice] Based on 162 circuit times, it looks like we
 don't need to wait so long for circuits to finish. We will now assume a
 circuit is too slow to use after waiting 10 seconds.
 Oct 04 19:38:10.075 [notice] Circuit build measurement period of 117281ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.

 Oct 04 19:38:12.271 [notice] Circuit build measurement period of 117330ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:38:16.805 [notice] Circuit build measurement period of 120054ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:38:21.109 [notice] Circuit build measurement period of 117447ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:38:38.345 [notice] Circuit build measurement period of 122752ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:41:05.013 [notice] Circuit build measurement period of 135039ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:42:06.013 [notice] Circuit build measurement period of 148555ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:42:06.013 [notice] Based on 169 circuit times, it looks like we
 need to wait longer for circuits to finish. We will now assume a circuit
 is too slow to use after waiting 11 seconds.
 Oct 04 19:44:08.013 [notice] Circuit build measurement period of 163425ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:45:09.013 [notice] Circuit build measurement period of 179783ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:45:09.013 [notice] Based on 171 circuit times, it looks like we
 need to wait longer for circuits to finish. We will now assume a circuit
 is too slow to use after waiting 12 seconds.
 Oct 04 19:46:10.013 [notice] Circuit build measurement period of 197779ms
 is more than twice the maximum build time we have ever observed. Capping
 it to 116950ms.
 Oct 04 19:46:10.013 [notice] Based on 172 circuit times, it looks like we
 need to wait longer for circuits to finish. We will now assume a circuit
 is too slow to use after waiting 13 seconds.
 }}}

 We never increase the value we're capping to, instead of doubling it.

--

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