Jump to content

High CPU usage 4.2.0.40


jeffu231

Recommended Posts

jad3675

Looks what I found in dmesg. This is in the near the end of Thursday night issues I was having. I was watching a show streaming from my rclone mount.

 

[Thu Oct 17 21:31:08 2019] INFO: task ffprobe:662 blocked for more than 120 seconds.
[Thu Oct 17 21:31:08 2019]       Not tainted 4.15.0-65-generic #74-Ubuntu
[Thu Oct 17 21:31:08 2019] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Thu Oct 17 21:31:08 2019] ffprobe         D    0   662  32413 0x00000004
[Thu Oct 17 21:31:08 2019] Call Trace:
[Thu Oct 17 21:31:08 2019]  __schedule+0x24e/0x880
[Thu Oct 17 21:31:08 2019]  schedule+0x2c/0x80
[Thu Oct 17 21:31:08 2019]  request_wait_answer+0x137/0x210
[Thu Oct 17 21:31:08 2019]  ? wait_woken+0x80/0x80
[Thu Oct 17 21:31:08 2019]  __fuse_request_send+0x86/0x90
[Thu Oct 17 21:31:08 2019]  fuse_request_send+0x27/0x30
[Thu Oct 17 21:31:08 2019]  fuse_send_readpages.isra.32+0xd1/0x120
[Thu Oct 17 21:31:08 2019]  fuse_readpages+0xfd/0x110
[Thu Oct 17 21:31:08 2019]  __do_page_cache_readahead+0x1c9/0x2c0
[Thu Oct 17 21:31:08 2019]  ondemand_readahead+0x11a/0x2c0
[Thu Oct 17 21:31:08 2019]  ? ondemand_readahead+0x11a/0x2c0
[Thu Oct 17 21:31:08 2019]  page_cache_sync_readahead+0x2e/0x50
[Thu Oct 17 21:31:08 2019]  generic_file_read_iter+0x7fb/0xbf0
[Thu Oct 17 21:31:08 2019]  ? lru_cache_add_active_or_unevictable+0x36/0xb0
[Thu Oct 17 21:31:08 2019]  ? __handle_mm_fault+0x9fd/0x1290
[Thu Oct 17 21:31:08 2019]  fuse_file_read_iter+0x4d/0x70
[Thu Oct 17 21:31:08 2019]  new_sync_read+0xe4/0x130
[Thu Oct 17 21:31:08 2019]  __vfs_read+0x29/0x40
[Thu Oct 17 21:31:08 2019]  vfs_read+0x8e/0x130
[Thu Oct 17 21:31:08 2019]  SyS_read+0x5c/0xe0
[Thu Oct 17 21:31:08 2019]  do_syscall_64+0x73/0x130
[Thu Oct 17 21:31:08 2019]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2

 

From the emby log, that is when 'The Good Place' stopped recording.

 

2019-10-17 21:31:00.065 Info LiveTV: Recording stopped: /home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.ts
2019-10-17 21:31:00.065 Info MediaSourceManager: Live stream native_ff80f93c46e0a0b178f0c4d61a5abab3_531dd78223127365bd1aa31ba1479ccd consumer count is now 0
2019-10-17 21:31:00.065 Info MediaSourceManager: Closing live stream 06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_native_ff80f93c46e0a0b178f0c4d61a5abab3_531dd78223127365bd1aa31ba1479ccd

2019-10-17 21:31:07.405 Info LiveTV: Triggering refresh on /home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.ts

2019-10-17 21:51:31.345 Error MediaEncoder: Timeout while running Ffprobe -i file:"/home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.mkv" -threads 0 -v info -print_format json -show_streams -show_chapters -show_format -show_data
                "filename": "file:/home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.mkv",
        Input #0, matroska,webm, from 'file:/home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.mkv':
        System.Exception: System.Exception: Error running ffprobe for file:"/home/dvr/shows/The Good Place (2016)/Season 4/The Good Place S04E04 Tinker, Tailor, Demon, Spy.mkv"

 

Of the four shows that were recorded back-to-back the last one if the only one that didn't have the ffprobe timeout (which is run shows on local storage). The timeout is due to the slow response of the storage, which I find interesting sine it includes fuser. I mark and convert recorded shows. They're recorded to local storage, then converted to mkv, and them marked with commercials. After that is done, I mv it from local storage (/home/dvr) to rclone storage. 'The Good Place' is 3.3GB in size and took 8 minutes to mv to cloud storage. 'Young Sheldon' was 2.3GB and took two minutes, but it was the first up. 'Perfect Harmony' is 3.3GB and took 15 minutes. Those high times, in my experience, are not normal for rclone moves.

 

I'm running a test now, trying to duplicate what was going on Thursday night.

 

John

 

Link to comment
Share on other sites

jad3675

So, I may have the answer to what is going on. I convert the .ts to .mkv and place it in the same directory where it was originally recorded, which is the 'Recorded TV Shows' library in emby - which had 'Real Time Monitoring' turned on. After the show is converted the script moves it to rclone, which is happening at the same time that emby is attempting to update the library. It would appear that rclone and fuser and ffprobe were not very happy with this combination going on at the same time.

 

The fix (is hopefully) to turn 'Real Time Monitoring' off for the library.

 

@@Q-Droid - thanks for the help. I really appreciate it.

 

John

Link to comment
Share on other sites

Q-Droid

Is the media moved or copied after conversion? If it's moved and not needed in the library then converting to a "staging" path could prevent the contention between Emby and rclone.

Link to comment
Share on other sites

jad3675

Is the media moved or copied after conversion? If it's moved and not needed in the library then converting to a "staging" path could prevent the contention between Emby and rclone.

 

It is moved. I've adjusted the script to put it in a scratch area, and I've turned off real time monitoring for the 'recorded tv' default library in emby. So far, testing looks good. Should know for sure on Thursday.

 

John

Link to comment
Share on other sites

jeffu231

I did some more testing. I downgraded my install to 4.1.1 and did a recording and captured the following top.

 

post-427901-0-69128800-1571614527_thumb.png

 

Then I installed the latest beta 4.3.0.15 and captured a top while recording the same channel and show as the first one.

 

post-427901-0-26860700-1571614527_thumb.png

 

I don't recall which version I was on specifically before upgrading to 4.2 where I noticed the difference, but you can see that 4.3 is using more cpu than the 4.1 version in this simple test. I am not sure what the ramifications of downgrading might be and if it was in the state it was before, but there is a noticeable difference between the two versions. 

 

 

 

Link to comment
Share on other sites

jad3675

I did some more testing. I downgraded my install to 4.1.1 and did a recording and captured the following top.

 

attachicon.gifScreen Shot 2019-10-20 at 11.41.39 AM.png

 

Then I installed the latest beta 4.3.0.15 and captured a top while recording the same channel and show as the first one.

 

attachicon.gifScreen Shot 2019-10-20 at 11.48.39 AM.png

 

I don't recall which version I was on specifically before upgrading to 4.2 where I noticed the difference, but you can see that 4.3 is using more cpu than the 4.1 version in this simple test. I am not sure what the ramifications of downgrading might be and if it was in the state it was before, but there is a noticeable difference between the two versions. 

 

Have you thought about installing something like Netdata to monitor this with more granularity and charts than top provdies? Or even using the free version of Datadog, like I do?

 

John

Link to comment
Share on other sites

jad3675

So, to wrap up my issues that may have temporarily derailed this thread...removing the 'real time monitoring' and moving the staging location for my DVR'ed shows has helped. A lot.

 

Here's a comparison between last Tuesday's recordings and last night's recording ending at 10pm. There's still some io.await as the system process the file, but it has improved significantly.

 

5db07de52e483_compare_week.png

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
×
×
  • Create New...