[tor-bugs] #24857 [Core Tor/Tor]: tor 0.3.1.9 100% cpu load
Tor Bug Tracker & Wiki
blackhole at torproject.org
Wed Jan 24 10:06:58 UTC 2018
#24857: tor 0.3.1.9 100% cpu load
--------------------------+-----------------------------------
Reporter: Eugene646 | Owner: (none)
Type: defect | Status: needs_information
Priority: Medium | Milestone:
Component: Core Tor/Tor | Version: Tor: 0.3.1.9
Severity: Normal | Resolution:
Keywords: cpu, windows | Actual Points:
Parent ID: | Points:
Reviewer: | Sponsor:
--------------------------+-----------------------------------
Comment (by creideiki):
I restarted the Tor service and watched it closely. The error message
"Failing because we have 4063 connections already" appears at the same
time as it starts using 100% CPU. This time it took 6 minutes.
At 3 minutes after starting the service, well after the log says the relay
is up and running, "perf top" looks nice and sane like this:
{{{
16.76% tor [.] curve25519_donna
3.18% libcrypto.so.1.0.0 [.] __bn_sqrx8x_reduction
1.93% libcrypto.so.1.0.0 [.] mulx4x_internal
1.79% libcrypto.so.1.0.0 [.] bn_sqrx8x_internal
1.62% tor [.] connection_bucket_refill
1.58% tor [.] tor_memcmp
1.40% libc-2.26.so [.] _int_malloc
1.37% libc-2.26.so [.] malloc
1.29% libcrypto.so.1.0.0 [.] sha256_block_data_order_avx2
0.99% libc-2.26.so [.] __memmove_avx_unaligned_erms
0.96% libc-2.26.so [.] _int_free
0.93% tor [.] tor_memeq
0.73% tor [.] buf_datalen
0.73% [kernel] [k] ___bpf_prog_run
0.71% [kernel] [k] syscall_return_via_sysret
0.61% libcrypto.so.1.0.0 [.] __ecp_nistz256_mul_montx
0.57% [kernel] [k] __fget
0.55% libcrypto.so.1.0.0 [.] __ecp_nistz256_sqr_montx
0.53% libcrypto.so.1.0.0 [.] sha1_block_data_order_avx2
0.52% tor [.] channel_update_bad_for_new_circs
0.46% libssl.so.1.0.0 [.] ssl_cipher_apply_rule.isra.1
0.45% libpthread-2.26.so [.] __pthread_mutex_lock
0.43% libc-2.26.so [.] cfree at GLIBC_2.2.5
0.42% libcrypto.so.1.0.0 [.] _aesni_ctr32_ghash_6x
}}}
After 6 minutes, when the error message has appeared in the log and the
process uses 100% CPU, "perf top" looks like this:
{{{
9.45% [kernel] [k] syscall_return_via_sysret
6.33% [unknown] [k] 0xfffffe00000b601e
5.16% [kernel] [k] ep_send_events_proc
3.48% [kernel] [k] ___bpf_prog_run
3.38% [kernel] [k] _raw_spin_lock_irqsave
3.19% [kernel] [k] read_tsc
3.06% [kernel] [k] __fget
2.75% libpthread-2.26.so [.] __pthread_mutex_lock
2.55% [kernel] [k] _raw_spin_unlock_irqrestore
2.49% [kernel] [k] seccomp_run_filters
2.33% libc-2.26.so [.] epoll_pwait
2.27% [kernel] [k] select_estimate_accuracy
2.25% libpthread-2.26.so [.] __pthread_mutex_unlock_usercnt
1.84% [kernel] [k] syscall_trace_enter
1.81% [kernel] [k] __seccomp_filter
1.78% libevent-2.1.so.6.0.2 [.] event_base_loop
1.65% [kernel] [k] ep_scan_ready_list.constprop.15
1.57% [unknown] [k] 0xfffffe000000601e
1.52% [kernel] [k] ep_poll
1.41% [kernel] [k] ktime_get_ts64
1.36% [kernel] [k] entry_SYSCALL_64_after_hwframe
1.35% libevent-2.1.so.6.0.2 [.] event_callback_activate_nolock_
1.29% [unknown] [k] 0xfffffe00000b6000
1.10% tor [.] assert_connection_ok
}}}
And says the Tor process is spending 65% of its time in the kernel.
Probably with those 69k/s epoll_pwait() calls.
Network statistics says it's still shuffling its 10Mb/s, though, so it's
doing something productive as well.
Final Tor log is not very interesting, but for completeness:
{{{
Jan 24 10:49:47.000 [notice] Tor 0.3.2.9 (git-9e8b762fcecfece6) opening
log file.
Jan 24 10:49:47.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Jan 24 10:49:48.000 [notice] Parsing GEOIP IPv6 file
/usr/share/tor/geoip6.
Jan 24 10:49:48.000 [notice] Configured to measure statistics. Look for
the *-stats files that will first be written to the data directory in 24
hours from now.
Jan 24 10:49:48.000 [notice] Your Tor server's identity key fingerprint is
CENSORED
Jan 24 10:49:48.000 [notice] Bootstrapped 0%: Starting
Jan 24 10:49:54.000 [notice] Starting with guard context "default"
Jan 24 10:49:54.000 [notice] Bootstrapped 80%: Connecting to the Tor
network
Jan 24 10:49:54.000 [notice] Self-testing indicates your ORPort is
reachable from the outside. Excellent.
Jan 24 10:49:54.000 [notice] Bootstrapped 85%: Finishing handshake with
first hop
Jan 24 10:49:55.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
Jan 24 10:49:56.000 [notice] Tor has successfully opened a circuit. Looks
like client functionality is working.
Jan 24 10:49:56.000 [notice] Bootstrapped 100%: Done
Jan 24 10:49:58.000 [notice] Self-testing indicates your DirPort is
reachable from the outside. Excellent. Publishing server descriptor.
Jan 24 10:50:00.000 [notice] Performing bandwidth self-test...done.
Jan 24 10:56:04.000 [warn] Failing because we have 4063 connections
already. Please read doc/TUNING for guidance.
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/24857#comment:5>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list