[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

tor eating CPU time




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