Janus-gateway: ICE thread sometimes pegs CPU

[mqp]

EDIT: Sorry, I thought my deployment included the ICE threading change, but actually this is from 0.4.1, right before the ICE threading change. I'm going to try it with master and see if it recurs.

Ubuntu 18.04 on EC2, Janus commit fd1013d822186cb8836c914286e2c86677e2f103.

Since updating to this Janus version it seems common for one of the ICE threads to begin taking up 100% CPU on one core, apparently inside g_poll on the GLib event loop. Here's a stack trace of that thread while it's happening:

Thread 23 (LWP 20372):
#0  0x00007f7b6c5ffe4d in poll () from /hab/pkgs/core/glibc/2.22/20170513201042/lib/libc.so.6
#1  0x00007f7b6e3676ab in g_poll () from /hab/pkgs/core/glib/2.50.3/20180416191835/lib/libglib-2.0.so.0
#2  0x00007f7b6e3555de in ?? () from /hab/pkgs/core/glib/2.50.3/20180416191835/lib/libglib-2.0.so.0
#3  0x00007f7b6e354f71 in ?? () from /hab/pkgs/core/glib/2.50.3/20180416191835/lib/libglib-2.0.so.0
#4  0x00007f7b6e3553c2 in g_main_loop_run ()
   from /hab/pkgs/core/glib/2.50.3/20180416191835/lib/libglib-2.0.so.0
#5  0x0000000000437071 in janus_ice_thread (data=0x7f7b4c00e0d0) at ice.c:2616
#6  0x00007f7b6e383cab in ?? () from /hab/pkgs/core/glib/2.50.3/20180416191835/lib/libglib-2.0.so.0
#7  0x00007f7b6db79434 in ?? () from /hab/pkgs/core/glibc/2.22/20170513201042/lib/libpthread.so.0
#8  0x00007f7b6c608dfd in clone () from /hab/pkgs/core/glibc/2.22/20170513201042/lib/libc.so.6

While this is happening, other threads are taking up an ordinarily small amount of CPU, memory seems constant, and general Janus operation seems to continue without obvious problems.

I'm not sure yet what's taking up the time, because I have a very rough understanding of how the GLib event machinery works. My first thought is that it must be something like "leaked" sources, where many sources get created and not removed, so a single poll takes longer and longer. However, on a cursory inspection, I can't see any particular sources that look like they should be leaking, so I don't know if that's right. I might see if I can use GDB to inspect the glib data structures, or increase my log level to see if any log messages that correlate with the presence or absence of sources are flying out. Further suggestions also welcome.

[lminiero]

Actually 0.4.1 does contain the ICE threading change, it's 0.4.0 that didn't. So I think you did indeed hit a bug. Do you have any way to replicate this? I did stress tests with our internal tool Jattack a few days ago and it didn't happen, so if you have any hint on your scenario that might help.

[vivaldi-va]

I've been noticing this happen to me too recently. Haven't been able to replicate it, however.

I'll try and set up an interface to get some info from the admin api to see if there's any patterns in the affected handles

[lminiero]

@vivaldi-va thx!

[atoppi]

@mquander thanks for the detailed report.
Try to enable as much debug symbols as you can (libc, glib, etc) and replicate the issue.
Then try to gather some other useful data like:

• how many fds is the problematic thread actually polling? (check nfds parameter in the bt with gdb)
• which are the fds involved? (navigate the fds array with gdb)
• once obtained the involved fds id, check them with lsof. Which kind of fd are they?
• in general, how many open fds is Janus handling? Check with lsof
• how many threads have Janus spawned? How many of these are ice-related? Check with pstree
  The presence of some ice related threads without serving any client might point to a leak.

[lminiero]

I just fixed an issue that may be related to this.

Specifically, in #1259 an attempt to do a new SIP call after the previous one had been rejected would always fail with a "still cleaning up" error. This turned out to be caused by the fact we were not quitting the loop in that case: in fact, in master we'd only break the loop when getting rid of the new "outgoing traffic" source. Anyway, that source would only created when ICE succeeded, so if that didn't happen, the ICE loop would never be quit. I fixed this in commit https://github.com/meetecho/janus-gateway/commit/71f25bba24b6178f40e94fb20062bc1a533808b0 by forcing a g_main_loop_quit when janus_ice_webrtc_hangup is called and no outgoing traffic source exists.

In this specific case (that I could replicate easily), the ICE loop would remain there even after the handle was closed, even though it would not use any CPU at all. Nevertheless, I think this may be related to your issue, as it still was a stuck loop. As such, please try with master instead when trying to replicate the issue in your environment.

[vivaldi-va]

deployed the lastest master, so i'll run that for a bit and see if this issue reoccurs

[mqp]

Verified that this still occurs on master post-SCTP-threading but pre-SIP-fix -- it happened to two threads overnight. I'll apply atoppi's debugging advice, and I'll try master post-SIP-fix.

[mqp]

I need to figure out how to get more debugging symbols in our production deployment where this issue obtains (it's a little painful because we're running it all under Habitat), but in the meantime, here's some info:

• At a time when there were only 4 active connections, there appear to be about 150 interesting open fds on the culprit thread. Here's the lsof output.
• At the same time, there were 46 iceloop threads. Here's the pstree output.

[mirkobrankovic]

@mquander this only affects SIP plugin ?

[mqp]

I doubt this is plugin-specific. I use my own plugin, not the SIP plugin.

[lminiero]

If it affects the ICE loop, it's definitely not plugin specific. Notice that I only mentioned the SIP plugin as a simple way by which the issue could be replicated: the issue was _NOT_ SIP related, it was caused by the fact that we were trying to close a PeerConnection where ICE had never started (or not succeeded), which would cause the iceloop to stay there forever. @mquander please try with that fix enabled, as the many (if not all) of the iceloops you still see there are probably caused by that: if that still happens, we can remove one variable from the equation.

[vivaldi-va]

Been running the fix added in https://github.com/meetecho/janus-gateway/commit/71f25bba24b6178f40e94fb20062bc1a533808b0 for about 20 hours, with some decent traffic through the video room. Performance has been fine thus far.

I'll keep an eye on it but it looks like that fix did the trick.

[mqp]

I've been running it for a few days with that fix and no sign of any issue.

[lminiero]

Excellent, thanks to you both for the feedback! I'll close this then. Feel free to reopen is it turns out to be still there.