100% CPU Usage

[rogerlipscombe 1]

Emby 4.1.1.0 on Ubuntu 18.04 on a Core i5 NUC, default plugins. After a few hours of running, the Emby server starts using 400% (4x100%) CPU. There's nothing interesting in embyserver.txt.

 

Restarting the OS or the service drops it back to essentially 0%, until it does it again.

 

I'm concerned because it's driving my CPU temps to ~95C, which is not a good thing.

 

What can I do to help diagnose this problem? Bear in mind that I am a software developer in my day job, so I know my way around gdb, strace, perf, etc.

[Luke 37053]

Hi there, can you please attach the emby server log from when this happened? thanks !

[rogerlipscombe 1]

Attached are log files covering the last day or so. I restarted the NUC at around 2019-07-15 21:26, and restarted the service at around 2019-07-16 08:21, both times because of high CPU usage. I'm not sure when the high CPU usage actually started.

 

One thing that occurs to me is that some of my libraries are on my NAS, mounted via CIFS. But: my NAS is turned off between 1am and 6am. Wondering if a scheduled scan in that time window gets itself confused...?

emby-server-logs.zip

Edited July 16, 2019 by rogerlipscombe

[Luke 37053]

Hi, does this occur primarily when the refresh guide scheduled task runs?

[rogerlipscombe 1]

I don't yet know exactly when it starts happening; I've left the following running to record CPU usage every 30 seconds. We'll see what it looks like in the morning. That'll (hopefully) give us a timestamp.

mpstat -u 30 | tee cpu.log

[Luke 37053]

Ok well if it aligns with the time when the refresh guide scheduled task runs, there's good news in that will be considerably faster with the upcoming 4.2 release. thanks.

[rogerlipscombe 1]

It started at 5 minutes before midnight (UTC+1, BST), so ~22:55 UTC:

23:55:03     all    2.91    0.00    1.49    0.31    0.00    0.08    0.00    0.00    0.00   95.21
23:55:33     all   17.95    0.00    8.01    0.20    0.00    0.20    0.00    0.00    0.00   73.64

Attached is a snippet of the server log for the time period in question. It started recording something from my HDHomeRun. That's OK; the problem is that the CPU usage was still maxed-out this morning, ~7 hours later.

 

The CPU is an i5-7260U, which means 2 cores, 4 threads; 17.95% user, 8.01% system ~= 25%, i.e. one maxed-out "CPU". which tracks with what I saw in htop in the morning -- a single EmbyServer thread using 100% CPU.

embyserver-63699004800.txt

[rogerlipscombe 1]

This is a new setup, so it's not got many scheduled recordings. It could be a complete coincidence that the recording started at close to midnight, and it might be that midnight is the problem. I'm going to schedule a couple of daytime TV recordings (i.e. not midnight) for today; we'll see if any of those trigger the problem.

[Luke 37053]

As a test, if you uninstall the dlna plugin and then restart the server, does that make a difference?

[rogerlipscombe 1]

As a test, if you uninstall the dlna plugin and then restart the server, does that make a difference?

 

It doesn't recur frequently enough to make this a good trial.

 

I'd prefer just to attach a debugger when it next happens and grab a call stack. It's a .NET app running under .NET Core, right? Got any pointers for doing that on Linux?

 

Edit -- Pointers for doing that on Linux:

• https://www.raydbg.com/2018/Debugging-Net-Core-on-Linux-with-LLDB/
• https://dotnet.microsoft.com/download/dotnet-core/2.2
• echo "plugin load /usr/share/dotnet/shared/Microsoft.NETCore.App/2.2.6/libsosplugin.so" >> ~/.lldbinit
• sudo lldb -p $(pgrep EmbyServer)
• clrstack

I've got to do some more reading to figure out how to switch to the 100% CPU thread in lldb to get the correct stack, but the above is a start.

Edited July 19, 2019 by rogerlipscombe

[Luke 37053]

With the release build? I haven't tried that, sorry.

[rogerlipscombe 1]

Happened again last night. Looking in htop shows two threads using a bunch of CPU. Attaching using lldb, I find that they're both thread pool threads (I assume Emby uses a lot of async/await), apparently attempting to update one of my libraries. Here's one:

Current frame: libcoreclr.so!___lldb_unnamed_symbol14331$$libcoreclr.so + 0x3bd
Child-SP         RetAddr          Caller, Callee
00007FC7A2D68B70 00007fc85a4aa582 libcoreclr.so!___lldb_unnamed_symbol14327$$libcoreclr.so + 0xd2, calling libcoreclr.so!___lldb_unnamed_symbol14331$$libcoreclr.so
00007FC7A2D68C10 00007fc85a4a9fe0 libcoreclr.so!WideCharToMultiByte + 0x70, calling libcoreclr.so!___lldb_unnamed_symbol14327$$libcoreclr.so
00007FC7A2D68C40 00007fc7e0a6d1f3 (MethodDesc 00007fc7e0637c68 + 0xe3 System.String.ConvertToAnsi(Byte*, Int32, Boolean, Boolean)), calling libcoreclr.so!WideCharToMultiByte
00007FC7A2D68C90 00007fc7e0a6d1f3 (MethodDesc 00007fc7e0637c68 + 0xe3 System.String.ConvertToAnsi(Byte*, Int32, Boolean, Boolean)), calling libcoreclr.so!WideCharToMultiByte
00007FC7A2D68D00 00007fc7e0bc7fc8 (MethodDesc 00007fc7e0668f38 + 0x78 System.StubHelpers.AnsiCharMarshaler.DoAnsiConversion(System.String, Boolean, Boolean, Int32 ByRef)), calling (MethodDesc 00007fc7e0637c68 + 0 System.String.ConvertToAnsi(Byte*, Int32, Boolean, Boolean))
00007FC7A2D68D40 00007fc7e0b89b91 (MethodDesc 00007fc7e0661df0 + 0xe1 System.StubHelpers.CSTRMarshaler.ConvertToNative(Int32, System.String, IntPtr)), calling (MethodDesc 00007fc7e0668f38 + 0 System.StubHelpers.AnsiCharMarshaler.DoAnsiConversion(System.String, Boolean, Boolean, Int32 ByRef))
00007FC7A2D68D50 00007fc85a1b933b libcoreclr.so!___lldb_unnamed_symbol4690$$libcoreclr.so + 0x2b, calling libcoreclr.so!___lldb_unnamed_symbol1305$$libcoreclr.so
00007FC7A2D68D80 00007fc7e109a134 (MethodDesc 00007fc7e17fbca8 + 0xd4 DomainBoundILStubClass.IL_STUB_PInvoke(System.String, FileStatus ByRef)), calling (MethodDesc 00007fc7e0661df0 + 0 System.StubHelpers.CSTRMarshaler.ConvertToNative(Int32, System.String, IntPtr))
00007FC7A2D68E40 00007fc7e190378d (MethodDesc 00007fc7e17fad40 + 0x2d System.IO.FileSystem.FileExists(System.String, Int32, ErrorInfo ByRef)), calling 00007fc7e1099fa0 (stub for Interop+Sys.Stat(System.String, FileStatus ByRef))
00007FC7A2D68E80 00007fc7e19018be (MethodDesc 00007fc7e17fc748 + 0x4e System.IO.PathInternal.TrimEndingDirectorySeparator(System.String)), calling (MethodDesc 00007fc7e17fc718 + 0 System.IO.PathInternal.EndsInDirectorySeparator(System.ReadOnlySpan`1<Char>))
00007FC7A2D68EE0 00007fc7e18fa2a6 (MethodDesc 00007fc7e17f85e0 + 0x66 System.IO.File.Exists(System.String)), calling (MethodDesc 00007fc7e17fad40 + 0 System.IO.FileSystem.FileExists(System.String, Int32, ErrorInfo ByRef))
00007FC7A2D68F00 00007fc7e4237dd3 (MethodDesc 00007fc7e35de8a0 + 0x63 Emby.LiveTV.EmbyTV.FileExists(System.String, System.String))
00007FC7A2D68F30 00007fc7e4237d35 (MethodDesc 00007fc7e35de890 + 0xf5 Emby.LiveTV.EmbyTV.EnsureFileUnique(System.String, System.String)), calling (MethodDesc 00007fc7e35de8a0 + 0 Emby.LiveTV.EmbyTV.FileExists(System.String, System.String))
00007FC7A2D68F90 00007fc7e41da5a7 (MethodDesc 00007fc7e367a560 + 0x9b7 Emby.LiveTV.EmbyTV+<RecordStream>d__99.MoveNext()), calling (MethodDesc 00007fc7e35de890 + 0 Emby.LiveTV.EmbyTV.EnsureFileUnique(System.String, System.String))
00007FC7A2D691F0 00007fc7e0ab47fd (MethodDesc 00007fc7e0648138 + 0x8d System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
00007FC7A2D69200 00007fc85a1adfe6 libcoreclr.so!___lldb_unnamed_symbol4564$$libcoreclr.so + 0x36, calling libcoreclr.so!__tls_get_addr

Here's the other:

urrent frame: (MethodDesc 00007fc7e065f130 + 0x3e System.IO.PathInternal.NormalizeDirectorySeparators(System.String))
Child-SP         RetAddr          Caller, Callee
00007FC7A0D66F80 00007fc7e0b334c7 (MethodDesc 00007fc7e0657e38 + 0x67 System.IO.Path.GetDirectoryName(System.String)), calling (MethodDesc 00007fc7e065f130 + 0 System.IO.PathInternal.NormalizeDirectorySeparators(System.String))
00007FC7A0D66FB0 00007fc7e4237ca4 (MethodDesc 00007fc7e35de890 + 0x64 Emby.LiveTV.EmbyTV.EnsureFileUnique(System.String, System.String))
00007FC7A0D67010 00007fc7e41da5a7 (MethodDesc 00007fc7e367a560 + 0x9b7 Emby.LiveTV.EmbyTV+<RecordStream>d__99.MoveNext()), calling (MethodDesc 00007fc7e35de890 + 0 Emby.LiveTV.EmbyTV.EnsureFileUnique(System.String, System.String))
00007FC7A0D67270 00007fc7e0ab47fd (MethodDesc 00007fc7e0648138 + 0x8d System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
00007FC7A0D67280 00007fc85a1adfe6 libcoreclr.so!___lldb_unnamed_symbol4564$$libcoreclr.so + 0x36, calling libcoreclr.so!__tls_get_addr

Notes:

 

• htop (with user-mode threads visible) will show you the PID of the threads using all the CPU
• in lldb, "thread list" will allow you to turn that PID into a thread index.
• "t NN" will switch to that thread.
• "dumpstack" gives you the above, which I've attached completely below.

 

emby-stacks.txt

[Luke 37053]

Thanks. That is the recording process trying to determine the recording file name to use.

[rogerlipscombe 1]

After some thinking, I'm not 100% convinced that is the cause. Both of the busy threads appear to be threadpool threads, doing a bunch of async stuff. That means that if there's a lot of different async stuff going on, then there'll be a lot of different things happening on those threads, seemingly unrelated.

 

It seems unusual to me that simply picking a name for a TV recording would use all of that CPU, and this might be a red herring. The fact that this call stack -- that identifies Emby.LiveTV -- appears in both of the busy threads is a strong hint that I'm wrong, though.

 

Instead, I wonder if what is happening is that Emby is rescanning my libraries, and that the rescan is triggered by the fact that my NAS vanishes (due to power-saving settings) every night.

 

I'm not going to be able to look at this for a few days, but when it next happens, and I next get a chance, I'll get a better sampling of what's going on on the busy thread, to see if it's consistently the LiveTV stack, or if there's more of a mixture of things.

Edited July 21, 2019 by rogerlipscombe

[Luke 37053]

Let us know how you get on. Thanks.

[groenator 11]

Ok well if it aligns with the time when the refresh guide scheduled task runs, there's good news in that will be considerably faster with the upcoming 4.2 release. thanks.

 

When is 4.2 release scheduled for?

Edited July 22, 2019 by groenator

[Luke 37053]

When is 4.2 release scheduled for?

 

Please see the beta FAQ:

https://emby.media/community/index.php?/topic/42284-emby-server-release-notes-beta-dev/

 

Thanks.

[rogerlipscombe 1]

Let us know how you get on. Thanks.

 

I'm back from vacation, and it happened again. I've spent about 10 minutes sampling the errant thread.

 

You were right. It's almost certainly the Emby.LiveTV.EmbyTV.EnsureFileUnique call. That's been in the stack every single time I've broken into the code.

 

Using strace, I can see that it's looping, continually doing this:

stat("/mounts/data/emby/livetv/recordings/Brooklyn Nine-Nine (2013)/Season 5/Brooklyn Nine-Nine S05E01 The Big House Pt.ts", {st_mode=S_IFREG|0644, st_size=440246012, ...}) = 0
stat("/mounts/data/emby/livetv/recordings/Brooklyn Nine-Nine (2013)/Season 5/Brooklyn Nine-Nine S05E01 The Big House Pt.ts", {st_mode=S_IFREG|0644, st_size=440246012, ...}) = 0
stat("/mounts/data/emby/livetv/recordings/Brooklyn Nine-Nine (2013)/Season 5/Brooklyn Nine-Nine S05E01 The Big House Pt.ts", {st_mode=S_IFREG|0644, st_size=440246012, ...}) = 0
stat("/mounts/data/emby/livetv/recordings/Brooklyn Nine-Nine (2013)/Season 5/Brooklyn Nine-Nine S05E01 The Big House Pt.ts", {st_mode=S_IFREG|0644, st_size=440246012, ...}) = 0

That filesystem (/mounts/data) is a local disk; the file exists, and is owned by the 'emby' user. As you can see the stat syscall is returning success. The first thing I thought of is that the filename is ... kinda long (116 characters). The directory name is actually a few characters shorter than it would normally have been, though (/mounts/data/emby/livetv/recordings/ vs /var/lib/emby/data/livetv/recordings). I actually have a symlink from /var/lib/emby/data/livetv/recordings to /mounts/data/emby/livetv/recordings; I wonder whether that's confusing things...? It shouldn't be: Emby is configured to use /mounts/data/emby/livetv/recordings

 

Restarting the server, or the PC, hasn't fixed the problem this time.

 

It's prompting me to install the latest version (currently on 4.1.1.0, latest 4.2.0.40). I'll do that and see if the situation is improved.

Edited July 30, 2019 by rogerlipscombe

[groenator 11]

I update emby to latest version, the guide refresh didn't improve, it's still using one core and always 100% usage.

[Luke 37053]

I update emby to latest version, the guide refresh didn't improve, it's still using one core and always 100% usage.

There are certain parts of it that can still improve more. Thanks for the feedback.

[rogerlipscombe 1]

It's prompting me to install the latest version (currently on 4.1.1.0, latest 4.2.0.40). I'll do that and see if the situation is improved.

 

Installing 4.2 seems to have fixed it. Thanks.

[Luke 37053]

Thanks for the feedback.

[groenator 11]

Installing 4.2 seems to have fixed it. Thanks.

What server are you running? How many cores do you have?

 

For me the update didn't fix it, is still using one core to refresh the guide. The problem is that I cant limit the usage to that core, as is always using 100%.

[rogerlipscombe 1]

What server are you running? How many cores do you have?

 

For me the update didn't fix it, is still using one core to refresh the guide. The problem is that I cant limit the usage to that core, as is always using 100%.

 

"It" for me was a different problem than you were seeing, so, honestly, you shoulda started your own thread.

[groenator 11]

"It" for me was a different problem than you were seeing, so, honestly, you shoulda started your own thread.

Wow! Very helpful dude! I already have a thread, I was just interested to see your server spec to get closer to my issue.