High latency of the first media playback request after idling

[Razrector 1]

Hi,

I'm experiencing long wait times whenever I want to play anything from my library after some idle time. This is reflected in the logs; first request to the `/Audio/` endpoint can take up to 20 seconds to be processed. The latency goes down to just a couple milliseconds on subsequent requests, even when attempting to play different items from various libraries.

Example log entry: 

2024-04-19 19:03:39.424 Info Server: http/1.1 Response 206 to host75. Time: 18756ms. GET http://emby_remote_ip/emby/Audio/106819/universal?UserId=....

This naturally led me to believe that HDD spin-up time is responsible for the bulk of the processing. I tried various other methods of accessing files on the drive when it was idling, the latency was nowhere near the mentioned 20s. 

I tried profiling the main server process using the `prof` utility, but I believe it spawns other processes for processing requests which I was unable to trace.

Are there any other methods of profiling or anything that would help me narrow down the issue?

My configuration:

Emby 4.8.1.0 proxied via Nginx (the issue persist even without the middleman)

RaspberryPi 5 8GB

2x Seagatte Ironwolf 4TB running in RAID1 via `mdadm` connected by USB adapters

Head of `embyserver.txt`:

Spoiler

2024-04-19 01:00:00.002 Info App: Emby Server Version: 4.8.1.0

2024-04-19 01:00:00.003 Info App: Emby

Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_arm64.deb

Operating system: Linux version 6.1.0-rpi7-rpi-v8 (debian-kernel@lists.debian.org) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREE

Framework: .NET 6.0.25

OS/Process: arm64/arm64

Runtime: opt/emby-server/system/System.Private.CoreLib.dll

Processor count: 4

Data path: /var/lib/emby

Application path: /opt/emby-server/system

2024-04-19 01:00:00.003 Info App: Logs path: /var/lib/emby/logs

2024-04-19 01:00:00.003 Info App: Cache path: /var/lib/emby/cache

2024-04-19 01:00:00.003 Info App: Internal metadata path: /var/lib/emby/metadata

2024-04-19 01:00:00.003 Info App: Transcoding temporary files path: /var/lib/emby/transcoding-temp

2024-04-19 01:00:00.003 Info App: Plugins:

Anime 1.5.6.0

Backup & Restore 1.6.3.0

Bluray Folder Support 1.0.2.0

Cinema Intros 1.0.47.0

Dvd Folder Support 1.0.0.0

Emby Guide Data 1.0.13.0

Fanart.tv 1.0.16.0

Last.fm 1.0.29.0

M3U TV Tuner 1.0.20.0

MovieDb 1.7.4.0

MusicBrainz 1.0.22.0

MyAnimeList 1.0.10.0

NapiSub 1.0.11.0

Nfo Metadata 1.0.79.0

Open Subtitles 1.0.54.0

Port Mapper 1.2.4.0

Studio Images 1.0.3.0

TheAudioDb 1.0.18.0

TheTVDB 1.4.5.0

Webhooks 1.0.35.0

XmlTV 1.1.8.0

 

Thanks!

Edited April 19 by Razrector

[Luke 37099]

Hi there, please attach the complete emby server log. 

But off the top of my head, maybe your media drives need time to spin up?

Thanks.

[Razrector 1]

Hi, thanks for the reply. Yeah, that's exactly what I was trying to rule out as an issue at first; tried accessing the files from the media drive directly via other programs, which is by no means a scientific method, but yielded different results that what I observed in Emby, with wait times closer to 1 second rather than 20.

Attaching the full Emby server log.

 

embyserver.txt

[Luke 37099]

I think this is the most likely reason but I can't really determine this from the log file. The reason for that is because Emby doesn't wake up your media drives directly, but rather, the file system handles that automatically whenever Emby tries to access a file.

If you wanted to prove this, then the best way to do that would be to disable the drive spin down on idling. Then you can still let the server machine idle but ensure the drives are running. I bet in that scenario the media will start quickly.

I'm not saying this approach is better or not. Obviously it is a tradeoff and you have to decide what you prefer. I personally let my NAS spin down so I also see this, but I take advantage of the library caching features so that it doesn't have to spin up until I actually press play.

[Razrector 1]

Thanks, this was indeed the reason behind the lag. However, I'll leave a note here for future readers as this wasn't as straightforward as just disabling the spindown all together (which I had done prior, using the recommended way via `hdparm` some time ago, without effect).

Some SATA controller manufacturers may implement the standard used for power management in a pretty dubious way, in the case of my Seagatte Ironwolf Pro, any software reported that the power management setting for HDD sleep / idle / spindown was off. All standard commands I used to check the drive's power state would first wake it before reporting anything, but one: `smartctl -i -n standby /dev/sd*`, which helped me realise when the device is in standby.

Since the power management settings were useless, I tried forcing the drive to stay awake by adding a cronjob that would read some data from the disk device, but that would not work as, at least what I suppose was happening, the kernel (or the device driver) would subsequently read the data from some cache and not use the disk at all. Ultimately, using `dd` with `iflag=direct` parameter, which as advertised, reads the data directly. Set this up as a cronjob and voila - all my issues have been solved!

Here's the cronjob for those interested:

*/3 * * * * dd if=/dev/sda of=/dev/null bs=1M count=1 iflag=direct

Thank you!

Edited April 20 by Razrector