Very slow response to RPC queries

[TwoLeaves]

In the course of tracking down the cause of some segfaults in the latest 0.15.2 release (TBD), I've found the current rtorrent master is very slow to respond to RPC requests (at least when queried via rtcontrol). A simple string search against torrent names takes somewhere between 10 seconds and two minutes (rather than nearly instantly as in the latest 0.15.2 release). This is regardless of whether rtorrent is compiled with tinyxml2 or xmlrpc-c. After testing against the small number of commits made since the last release, it seems the regression is due to "Fix SCGI threading and added missing header." commit. I tested on macOS and ArchLinux with the same behaviour on both.

[mirolm]

I can second that - after this commit flood loads with like 1-2 seconds delay for me.

[rakshasa]

SCGI now does callbacks to the main thread to call commands instead of acquiring global lock.

It should not cause any noticeable performance issues, however there might be a bug somewhere so we need to figure out where it gets stuck.

[Webbeh]

Hi,

I can confirm this issue using 0.15.2 in Archlinux.

Flood becomes extremely unresponsive (and isn't able to add new torrents anymore). Reverting to 0.15.1 fixes the issue instantly with no config change.

I only tried with scgi through local socket, not through network port though.

Note that this applies to a brand new install of Arch + flood with nothing added to rtorrent yet.

It simply feels like rtorrent just doesn't send data back to the scgi socket basically.

[helamonster]

FYI: I am also seeing this with git master using --with-xmlrpc-tinyxml2 and this config:

scgi_port = 0.0.0.0:5000

network.rpc.use_xmlrpc.set = true
network.rpc.use_jsonrpc.set = false

On the last few attempts, it takes from 5 to 21 seconds to add a magnet url, for example.

[rakshasa]

Try rtorrent/libtorrent master.

[Webbeh]

@rakshasa After compiling the latest libtorrent+ rtorrent from master, I don't see much change compared to what I previously saw.
Commits : c9ee12b and a8622e5

The first 2-3 seconds seem to work perfectly fine, and then the slowdown occurs again.

It kinda feels like rtorrent is "polling" for messages on the scgi socket every 20-30 seconds, and then answering only then, is that possible?

[xombiemp]

I'm seeing major slowdowns with latest master too. ruTorrent initial load takes 20-30 seconds Novik/ruTorrent#2888

I'm using the Archlinux package that is currently using the latest master
0.15.2-3 https://gitlab.archlinux.org/archlinux/packaging/packages/rtorrent/-/commits/main

Rolling back to version 0..15.2-1, which appears to be using the official 0.15.2 release tag, fixes the slowness issue.

[rakshasa]

Could someone with these issues try to run a cpu profiler, like perf?

[helamonster]

I ran perf rtorrent with an empty list of torrents, remotely sent a load.start command (which took a tens of seconds) and then quit. The rtorrent process doesn't appear to be CPU-bound during that time. I would agree with @Webbeh in that it feels like there's a polling going on since sometimes it takes 1 second and other times it takes tens of seconds. Regardless, here is a truncated output of perf report:

Samples: 277  of event 'cycles', Event count (approx.): 90852680
Overhead  Command        Shared Object          Symbol
   8.44%  rtorrent main  libncursesw.so.6.3     [.] wnoutrefresh
   5.03%  rtorrent main  libncursesw.so.6.3     [.] werase
   2.76%  rtorrent main  [kernel.kallsyms]      [k] 0xffffffffb34b87e7
   2.08%  rtorrent main  libc.so.6              [.] wcwidth
   1.67%  rtorrent       [kernel.kallsyms]      [k] 0xffffffffb34b8c56
   1.65%  rtorrent       ld-linux-x86-64.so.2   [.] 0x000000000000b78d
   1.59%  rtorrent main  libncursesw.so.6.3     [.] newwin_sp
   1.47%  rtorrent main  [kernel.kallsyms]      [k] 0xffffffffb3107ca3
   1.38%  rtorrent main  libc.so.6              [.] 0x00000000000ba97a
   1.11%  rtorrent       [kernel.kallsyms]      [k] 0xffffffffb3c01210
   1.08%  rtorrent main  [kernel.kallsyms]      [k] 0xffffffffb3c01680
   0.75%  rtorrent main  [kernel.kallsyms]      [k] 0xffffffffb3163f5f
   0.75%  rtorrent main  [kernel.kallsyms]      [k] 0xffffffffb312a98a

Please let me know what else I can provide to help.

[Webbeh]

Just did a perf record rtorrent as well.

Loaded a few (finished) torrents in the session, all went well, rtorrent's ncurses UI was responsive.

Flood (XMLRPC over socket) took 30 solid seconds to show anything (it saw the socket was up and tried to connect to it but just took forever) and failed to load the archlinux ISO (magnet) after 30 seconds...

Here's the top results :

headers :

# captured on    : Tue Apr 22 17:01:21 2025
# header version : 1
# data offset    : 296
# data size      : 1131880
# feat offset    : 1132176
# hostname : torrents
# os release : 6.14.2-arch1-1
# perf version : 6.14-1
# arch : x86_64
# nrcpus online : 5
# nrcpus avail : 5
# cpudesc : QEMU Virtual CPU version 2.5+
# cpuid : GenuineIntel,15,107,1
# total memory : 8024044 kB
# cmdline : /usr/bin/perf record rtorrent
# event : name = task-clock:uppp, , id = { 48, 49, 50, 51, 52 }, type = 1 (software), size = 136, config = 0x1 (PERF_COUNT_SW_TASK_C>
# CPU_TOPOLOGY info available, use -I to display
# NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, breakpoint = 5, kprobe = 8, msr = 10, software = 1, tool = 4294967294, tracepoint = 2, uprobe = 9
# CACHE info available, use -I to display
# time of first sample : 3297.498419
# time of last sample : 3443.608164
# sample duration : 146109.744 ms
# MEM_TOPOLOGY info available, use -I to display
# cpu pmu capabilities: not available
# missing features: TRACING_DATA BRANCH_STACK GROUP_DESC AUXTRACE STAT CLOCKID DIR_FORMAT COMPRESSED CLOCK_DATA HYBRID_TOPOLOGY

Data

# Total Lost Samples: 0
#
# Samples: 28K of event 'task-clock:uppp'
# Event count (approx.): 7024750000
#
# Overhead  Command        Shared Object          Symbol                                                                             
# ........  .............  .....................  ..........................................................................................................................
#
    25.63%  rtorrent main  libc.so.6              [.] 0x000000000009dbe2
    19.61%  rtorrent main  [vdso]                 [.] __vdso_gettimeofday
     6.25%  rtorrent main  libc.so.6              [.] 0x0000000000091e33
     5.36%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::PollEPoll::poll(int)
     4.36%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::utils::Thread::event_loop()
     4.05%  rtorrent main  libc.so.6              [.] pthread_mutex_lock
     3.65%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::ThreadMain::call_events()
     2.70%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::PollEPoll::perform()
     2.33%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::PollEPoll::do_poll(long, int)
     2.30%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::ThreadMain::next_timeout_usec()
     2.29%  rtorrent main  rtorrent               [.] 0x0000000000049360
     2.01%  rtorrent main  libtorrent.so.24.0.0   [.] torrent::signal_bitfield::work()
     1.84%  rtorrent main  libc.so.6              [.] pthread_self
     1.83%  rtorrent main  libc.so.6              [.] epoll_wait
     1.67%  rtorrent main  rtorrent               [.] 0x00000000000485b0
     1.55%  rtorrent main  libc.so.6              [.] pthread_mutex_unlock
     1.13%  rtorrent main  rtorrent               [.] 0x000000000004938c
     1.02%  rtorrent main  rtorrent               [.] 0x0000000000049385
     1.01%  rtorrent main  libc.so.6              [.] 0x0000000000091e39
     0.58%  rtorrent main  libc.so.6              [.] 0x000000000009a6b4
     0.57%  rtorrent main  rtorrent               [.] 0x0000000000049365
     0.49%  rtorrent main  rtorrent               [.] 0x0000000000049300
     0.45%  rtorrent main  rtorrent               [.] 0x00000000000494aa
     0.42%  rtorrent main  libstdc++.so.6.0.33    [.] std::istream::get()
     0.28%  rtorrent main  libstdc++.so.6.0.33    [.] std::istream::sentry::sentry(std::istream&, bool)
     0.28%  rtorrent main  rtorrent               [.] 0x000000000004930b
     0.22%  rtorrent main  rtorrent               [.] 0x000000000004936c
     0.18%  rtorrent main  rtorrent               [.] 0x00000000000493eb
     0.17%  rtorrent main  libc.so.6              [.] 0x000000000009a667
     0.14%  rtorrent main  libncursesw.so.6.5     [.] werase
     0.14%  rtorrent main  rtorrent               [.] 0x00000000000493a2
     0.12%  rtorrent main  rtorrent               [.] 0x00000000000493bc
     0.11%  rtorrent main  libncursesw.so.6.5     [.] wnoutrefresh
     0.11%  rtorrent main  rtorrent               [.] 0x0000000000049321
     0.10%  rtorrent main  rtorrent               [.] 0x00000000000493fe
     0.10%  rtorrent main  libc.so.6              [.] 0x000000000009a674
     0.10%  rtorrent main  libncursesw.so.6.5     [.] waddnstr
     0.10%  rtorrent main  libc.so.6              [.] wcwidth
     0.10%  rtorrent main  rtorrent               [.] 0x000000000004949a
     0.09%  rtorrent main  rtorrent               [.] 0x00000000000493ed
     0.09%  rtorrent main  libncursesw.so.6.5     [.] unctrl_sp
     0.09%  rtorrent main  libc.so.6              [.] wctob
     0.09%  rtorrent main  rtorrent               [.] 0x00000000000494ae
     0.08%  rtorrent main  libc.so.6              [.] cfree
     0.08%  rtorrent main  rtorrent               [.] 0x000000000004936a
     0.07%  rtorrent main  libc.so.6              [.] 0x000000000009a6d4
     0.07%  rtorrent main  rtorrent               [.] 0x00000000000485b4
     0.07%  rtorrent main  rtorrent               [.] 0x00000000000493c2
     0.06%  rtorrent main  libc.so.6              [.] 0x0000000000091e6f
     0.06%  rtorrent main  rtorrent               [.] 0x000000000004937a
     0.06%  rtorrent main  rtorrent               [.] 0x00000000000493f7
     0.06%  rtorrent main  rtorrent               [.] 0x0000000000049452
     0.05%  rtorrent main  libc.so.6              [.] malloc
     0.05%  rtorrent main  rtorrent               [.] 0x0000000000049364
     0.05%  rtorrent main  rtorrent               [.] 0x0000000000049394
     0.05%  rtorrent main  libc.so.6              [.] __ctype_b_loc
     0.05%  rtorrent main  libc.so.6              [.] 0x0000000000091e1f

[helamonster]

I just ran a similar test, this time with strace:
strace -f -tt -o strace.log rtorrent -s . -d .

I ran the command to send the XMLRPC load.start command between 2 timestamps:
date +%H:%M:%S.%6N ; rtorrentctl ... ; date +%H:%M:%S.%6N witch output these timestamps:

10:17:18.224110
10:17:37.008551

The strace log appears to show that the process that received the request (2067728) was in an epoll_wait() for about 19 seconds from 10:17:18.232592 to 10:17:37.004135. Here is an abbreviated version of the log:

...
2067728 10:17:18.231422 accept(22, {sa_family=AF_INET6, sin6_port=htons(44050), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28]) = 23
2067728 10:17:18.231644 epoll_ctl(20, EPOLL_CTL_ADD, 23, {events=EPOLLIN, data={u32=23, u64=23}}) = 0
2067728 10:17:18.231747 epoll_ctl(20, EPOLL_CTL_MOD, 23, {events=EPOLLIN|EPOLLERR, data={u32=23, u64=23}}) = 0
2067728 10:17:18.231830 accept(22, 0x7fe30535cb30, [28]) = -1 EAGAIN (Resource temporarily unavailable)
2067728 10:17:18.231942 epoll_wait(20, [{events=EPOLLIN, data={u32=23, u64=23}}], 1024, 600001) = 1
2067728 10:17:18.232030 recvfrom(23, "60:CONTENT_LENGTH\000565\0SCGI\0001\0REQ"..., 2047, 0, NULL, NULL) = 629
2067728 10:17:18.232274 epoll_ctl(20, EPOLL_CTL_MOD, 23, {events=EPOLLERR, data={u32=23, u64=23}}) = 0
2067728 10:17:18.232416 sendto(5, "a", 1, 0, NULL, 0) = 1
2067724 10:17:18.232533 <... epoll_wait resumed>[{events=EPOLLIN, data={u32=6, u64=6}}], 1024, 997) = 1
2067728 10:17:18.232592 epoll_wait(20,  <unfinished ...>
2067724 10:17:18.232676 recvfrom(6, "a", 256, 0, NULL, NULL) = 1
2067724 10:17:18.232912 epoll_wait(14, [], 1024, 768) = 0
... more similar output from the main process 2067724 but nothing from process 2067728 until ...
2067728 10:17:37.004135 <... epoll_wait resumed>[{events=EPOLLIN, data={u32=19, u64=19}}], 1024, 600001) = 1
2067724 10:17:37.004209 openat(AT_FDCWD, "magnet:?xt=urn:btih:aabbcc22fe59f62b677ef52c06c0228792f4fa56&dn=Redacted-Torrent-Title-abcdefghijklmnopqrstuvwxyz0123456.ext&tr=udp%3A%2F%2Ftracker.opentrackr.org%3A1337%2Fa...announce.rtorrent", O_RDONLY <unfinished ...>
2067728 10:17:37.004249 recvfrom(19,  <unfinished ...>
2067724 10:17:37.004295 <... openat resumed>) = -1 ENAMETOOLONG (File name too long)
2067728 10:17:37.004351 <... recvfrom resumed>"a", 256, 0, NULL, NULL) = 1
2067724 10:17:37.004407 openat(AT_FDCWD, "magnet:?xt=urn:btih:aabbcc22fe59f62b677ef52c06c0228792f4fa56&dn=Redacted-Torrent-Title-abcdefghijklmnopqrstuvwxyz0123456.ext&tr=udp%3A%2F%2Ftracker.opentrackr.org%3A1337%2Fa...announce.libtorrent_resume", O_RDONLY <unfinished ...>
2067728 10:17:37.004464 epoll_ctl(20, EPOLL_CTL_MOD, 23, {events=EPOLLOUT|EPOLLERR, data={u32=23, u64=23}} <unfinished ...>
2067724 10:17:37.004500 <... openat resumed>) = -1 ENAMETOOLONG (File name too long)
2067728 10:17:37.004534 <... epoll_ctl resumed>) = 0
2067728 10:17:37.004572 epoll_wait(20, [{events=EPOLLOUT, data={u32=23, u64=23}}], 1024, 600001) = 1
2067728 10:17:37.004640 sendto(23, "Status: 200 OK\r\nContent-Type: te"..., 174, MSG_NOSIGNAL, NULL, 0) = 174
2067728 10:17:37.004833 epoll_ctl(20, EPOLL_CTL_MOD, 23, {events=EPOLLERR, data={u32=23, u64=23}}) = 0
2067728 10:17:37.004908 epoll_ctl(20, EPOLL_CTL_DEL, 23, 0x7fe30535c714) = 0
2067728 10:17:37.004972 close(23)       = 0

[Webbeh]

I'm sorry, I'm not comfortable enough with those tools to know what I'd be looking for. If you want me to perform any specific checks I'll be glad to do it, you just have to let me know what you're looking for exactly I guess

[rakshasa]

Check perf lock.