tor eating CPU time

Valient Gough vgough at pobox.com
Fri Jan 28 11:56:12 UTC 2005


I upgraded to 0.0.9.3 last weekend, and it dropped tor's average CPU 
usage by almost half.

However thing have been slowly getting worse.  Saturday stats show about 
30% CPU average usage, increasing slowly to a little over 40% on Wed, 
then about 50% by Thursday, and about 12 hours ago tor jumped to 100% 
cpu usage and has not taken a rest since then.

The strange thing is that this doesn't correlate with traffic served.  
Tor traffic has been steadily averaging about 200k/sec, and started 
dropping about 12 hours ago by as much as a factor of 2 (much higher 
variation though).  So, CPU time increased, but network traffic decreased...

Looking through my server monitoring logs, I don't see any correlation 
against network usage or number of open TCP connections.   I'm about to 
restart TOR, but before I get into the habbit of periodic restarts, is 
there anything I can do to get information about the problem?

In case it helps, here are the messages from warnings.log from about the 
time when the CPU usage first pegged at 100%  (the cpu pegged at about 
15:50 server local time +- 10 minutes):

Jan 27 12:56:04.178 [warn] Bug: Double mark-for-close on connection.
Jan 27 12:56:04.178 [warn] Duplicate call to connection_mark_for_close 
at relay.
c:567 (first at connection.c:861)
Jan 27 15:08:30.397 [warn] parse_addr_port(): Port ':80' out of range
Jan 27 15:08:30.397 [warn] connection_exit_begin_conn(): Unable to parse 
addr:po
rt in relay begin cell. Dropping.
Jan 27 15:40:59.192 [warn] Bug: Double mark-for-close on connection.
Jan 27 15:40:59.193 [warn] Duplicate call to connection_mark_for_close 
at relay.
c:567 (first at connection.c:861)
Jan 27 17:08:14.508 [warn] rend_mid_rendezvous(): Rejecting RENDEZVOUS1 
cell wit
h unrecognized rendezvous cookie A2C5DA1B
Jan 27 17:35:31.927 [warn] onion_skin_server_handshake(): Couldn't 
decrypt onion
skin: client may be using old onion key
Jan 27 17:35:31.928 [warn] cpuworker_main(): onion_skin_server_handshake 
failed.
Jan 27 17:35:31.930 [warn] connection_cpu_process_inbuf(): decoding 
onionskin fa
iled. Closing.
Jan 27 17:36:40.743 [warn] onion_skin_server_handshake(): Couldn't 
decrypt onion
skin: client may be using old onion key
Jan 27 17:36:40.743 [warn] cpuworker_main(): onion_skin_server_handshake 
failed.
Jan 27 17:36:40.746 [warn] connection_cpu_process_inbuf(): decoding 
onionskin fa
iled. Closing.
Jan 27 17:37:27.594 [warn] onion_skin_server_handshake(): Couldn't 
decrypt onion
skin: client may be using old onion key
Jan 27 17:37:27.594 [warn] cpuworker_main(): onion_skin_server_handshake 
failed.
Jan 27 17:37:27.596 [warn] connection_cpu_process_inbuf(): decoding 
onionskin fa
iled. Closing.

I only see 10 log messages for the last 4 hours, but CPU is 100%, so it 
isn't in a busy loop logging messages.

Here are the messages tagged with 'Bug':
 > grep Bug tor/warnings.log | cut -c 20- | sort | uniq -c
      4  [warn] Bug: Double mark-for-close on connection.
     10  [warn] connection_about_to_close_connection(): Bug: Edge 
connection hasn't sent end yet?
    268  [warn] connection_edge_end(): Bug: Calling connection_edge_end 
on an already ended stream?
      3  [warn] connection_or_connect(): Bug: Request to connect to 
myself! Failing.


any ideas?

Valient





More information about the tor-talk mailing list