Unresponsive Interface - FREQUENT issue

Plex Media Server Desktops & Laptops
23

I just noticed these using your version:

==> /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs/Plex Media Server.log <==
May 25, 2019 22:12:28.170 [0x7f974e7fc700] WARN - Waited one whole second for a busy database.
May 25, 2019 22:12:28.242 [0x7f975b3fe700] WARN - Waited one whole second for a busy database.
May 25, 2019 22:12:29.184 [0x7f974e7fc700] ERROR - Failed to begin transaction (../Statistics/StatisticsManager.h:201) (tries=5): Cannot begin transaction. database is locked
May 25, 2019 22:12:30.000 [0x7f97527fa700] ERROR - Error issuing curl_easy_perform(handle): 28
May 25, 2019 22:12:30.000 [0x7f97527fa700] DEBUG - HTTP simulating 408 after curl timeout
May 25, 2019 22:12:30.001 [0x7f97527fa700] ERROR - Error parsing content.
May 25, 2019 22:12:30.001 [0x7f97527fa700] ERROR - Error parsing XML response for update.
May 25, 2019 22:12:30.002 [0x7f97527fa700] DEBUG - Media Analyzer: Item 4659 is already in progress.
May 25, 2019 22:12:30.468 [0x7f975b3fe700] WARN - Waited one whole second for a busy database.
May 25, 2019 22:12:30.638 [0x7f974e7fc700] WARN - Waited one whole second for a busy database.
May 25, 2019 22:12:31.651 [0x7f974e7fc700] ERROR - Failed to begin transaction (../Statistics/StatisticsManager.h:201) (tries=6): Cannot begin transaction. database is locked
May 25, 2019 22:12:32.705 [0x7f975b3fe700] WARN - Waited one whole second for a busy database.
May 25, 2019 22:12:33.580 [0x7f974e7fc700] WARN - Waited one whole second for a busy database.
24

Thought I’d throw in some extra data. In case this is relevant. (Google results appear to make it so)

Server throughput

dd if=/dev/zero of=/tmp/test1.img bs=1G count=1 oflag=dsync

OUTPUT: 1+0 records in
1+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 6.29532 s, 171 MB/s

Server latency time:

dd if=/dev/zero of=/tmp/test2.img bs=512 count=1000 oflag=dsync

OUTPUT:
1000+0 records in
1000+0 records out
512000 bytes (512 kB, 500 KiB) copied, 8.61905 s, 59.4 kB/s

This is on a VM on a server whose datastore is a hardware raid 10 of 8 drives, I believe they’re all 10k rpm.

hdparm -t /dev/sda1

/dev/sda1:

Timing buffered disk reads: 344 MB in 3.00 seconds = 114.64 MB/sec

root@GPlex:~# ## OR ##

root@GPlex:~# hdparm -t /dev/sda

/dev/sda:

Timing buffered disk reads: 330 MB in 3.00 seconds = 109.97 MB/sec

25

Unfortunately your fix is not related to my problem. My UI dies because the Plex database locks and follow-on operations fail. I assume this is because of drive access speed? I haven’t yet tested building a server where Plex runs entirely out of the ram, although the metadata folder will probably still have to be disk-based.

@ChuckPa can you elaborate which folder(s) would be required to run from RAM to ‘increase database reaction times’?

26

Chuck, I am having a similar issue. I am getting frequent stops in the server. I am attaching the logs for your review. Thanks.

Logs.zip (11.0 MB)

27

I realize today is an American holiday and maybe not so many people on the forum but has anyone figured out a way around this whole locked database issue? Would it be prudent to try and run Plex almost entirely from RAM?

28

No one has commented on this, I assume because it’s fallen off the radar. I’m going to attempt to load the plex database into a ram drive.

Program flow should look like

  • onstart:
    • create drive > copy plex db files > symlink db folder
  • onstop:
    • shutdown plex > mv db files back > unmount ram drive

I know it’s said over and over don’t put your database on the network but I searched the forum and didn’t see this anywhere. I’m hoping these database lock issues are simply a matter of not enough speed, but 8 x 10k sata2 drives in a raid10 config is a modestly fast storage.

We’ll see. @ChuckPa if you have any input on this I’d be interested to hear your thoughts.

Not having a functional plex server at the moment I can’t estimate how big the database files will get. I obviously want to exclude the metadata as that folder is hundreds of gigs last I checked.

If I can get the damn thing working without the ramdrive - long enough to index the media - maybe I’ll know if this is even possible or if this would just take an insane amount of ram. My server has 18 slots for ram… , so, it’s quite expandable I’m only using like 4 of them. Just thinking out loud.

29

This hasn’t fallen off the radar. Engineering is trying to figure out where the problem is rooted.

For this reason, and knowing the CI changed as of 1.15.0, I suggested using 1.14.1.5488 which is known to not demonstrate these symptoms.

Is everyone in this thread using 1.14.1.5488 ?

I’m still contemplating your ramdrive config.

30

if a Ramdrive is in use:

  1. The service ExecStartPre would need modifying
  2. An ExecStop clause would need to be added.

In those clauses, the data transfers could be performed.
Additionally, a mount --bind could be used to overlay the Ramdisk over the Databases directory**.

If you want to be swoopy about this, an overlayfs could be used to allow the mass of metadata to remain on the main filesystem below. Only the newly added data would end up in the Ramdisk. This is much easier to manage. OverlayFS is how Docker works.

It would be a fair piece of scripting work but not too difficult. Definitely detail rich

31

Unfortunately, the version you provided me did demonstrate these exact same symptoms.

This is a consideration. I started with a blank Debian 9.9.0 x64 last night, expert install, tasksel limited to ssh server and basic system utilities.

I installed the latest stable and only added one library. Tonight I’ll be able to check the status of that. If it continues to give database locks I’m going to script whatever-the-hell I need to in order to ramdrive the database itself but not the metadata. Your recommendations sound like a good way to go. I’ll probably start a public git repo on the subject if I have to travel down this road.

32

Just an update. I can’t explain this.

I rebuilt a Debian 9.9.0 vm on my ESXi host. I used Mr Worf’s plexupdate script to install Plex.

I mounted rclone with the following:
Conf:

[GDrive]
type = drive
client_id = **redacted**
client_secret = **redacted**
scope = drive
team_drive = **redacted**
token = **redacted**
use_trash = false
chunk_size = 16M

[GCrypt]
type = crypt
remote = GDrive:
filename_encryption = standard
directory_name_encryption = true
password = **redacted**
password2 = **redacted**

SystemD Service

[Unit]
Description=rclone-gcrypt
After=network-online.target

[Service]
Type=simple
User=root
Group=root
ExecStart=/usr/bin/rclone mount GCrypt: /mnt/GCrypt --allow-other --buffer-size 256M --dir-cache-time 24h --drive-chunk-size 128M --vfs-read-chunk-size 128M --vfs-read-chunk-size-limit off --use-mmap
ExecStop=/bin/fusermount -uz /mnt/GCrypt
Restart=always
RestartSec=2

[Install]
WantedBy=multi-user.target

I added one library at first, it scanned fine. I added the others and it’s on my last library, still scanning just fine. Interface is fully responsive, everything appears to be working as expected.

I’m absolutely at a loss to explain WHY it’s working.
tail -f *.log

==> Plex Media Server.log <==
Jun 04, 2019 17:31:05.344 [0x7f6aa9ffb700] DEBUG - Request: [127.0.0.1:35244 (Loopback)] GET /library/changestamp (5 live) GZIP Signed-in Token (Duvrazh)
Jun 04, 2019 17:31:05.345 [0x7f6afaffd700] DEBUG - Completed: [127.0.0.1:35244] 200 GET /library/changestamp (5 live) GZIP 0ms 467 bytes

==> Plex Media Scanner.log <==
Jun 04, 2019 17:31:05.345 [0x7fe22a503240] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/library/changestamp
Jun 04, 2019 17:31:05.345 [0x7fe22a503240] DEBUG - Added new metadata item () with ID 24296
Jun 04, 2019 17:31:05.346 [0x7fe21b893700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/:/metadata/flushMetadataCounterCache

==> Plex Media Server.log <==
Jun 04, 2019 17:31:05.346 [0x7f6afbfff700] DEBUG - Request: [127.0.0.1:35246 (Loopback)] GET /:/metadata/flushMetadataCounterCache (5 live) GZIP Signed-in Token (Duvrazh)
Jun 04, 2019 17:31:05.346 [0x7f6afaffd700] DEBUG - Completed: [127.0.0.1:35246] 200 GET /:/metadata/flushMetadataCounterCache (5 live) GZIP 0ms 166 bytes

==> Plex Media Scanner.log <==
Jun 04, 2019 17:31:05.346 [0x7fe21b893700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/:/metadata/flushMetadataCounterCache
Jun 04, 2019 17:31:07.434 [0x7fe22a503240] DEBUG -       * Scanning New Girl Season 2 Episode 10
Jun 04, 2019 17:31:07.434 [0x7fe22a503240] DEBUG - Looking for path match for [/mnt/GCrypt/TV/New Girl/Season 2/New Girl - S02E10 - Bathtub WEBDL-1080p.mkv]
Jun 04, 2019 17:31:07.435 [0x7fe22a503240] DEBUG - Skipping hash check, no size match for 948045681 bytes.
Jun 04, 2019 17:31:07.436 [0x7fe22a503240] DEBUG - No match for hash.
Jun 04, 2019 17:31:07.436 [0x7fe22a503240] DEBUG - Checking descendants of New Girl
Jun 04, 2019 17:31:07.437 [0x7fe22a503240] DEBUG -  -> Searching down into New Girl/Season 1
Jun 04, 2019 17:31:07.437 [0x7fe22a503240] DEBUG - Checking descendants of New Girl/Season 1
Jun 04, 2019 17:31:07.438 [0x7fe22a503240] DEBUG -  -> FOUND metadata item (show)
Jun 04, 2019 17:31:07.438 [0x7fe22a503240] DEBUG -  -> We found a local media item with rooted metadata in New Girl/Season 1
Jun 04, 2019 17:31:07.438 [0x7fe22a503240] DEBUG - Found existing show 24260
Jun 04, 2019 17:31:07.439 [0x7fe22a503240] DEBUG - Found existing leaf with index 10.
Jun 04, 2019 17:31:07.439 [0x7fe22a503240] DEBUG - Downloading document http://127.0.0.1:32400/library/changestamp
Jun 04, 2019 17:31:07.439 [0x7fe22a503240] DEBUG - HTTP requesting GET http://127.0.0.1:32400/library/changestamp

==> Plex Media Server.log <==
Jun 04, 2019 17:31:07.440 [0x7f6ac5ffb700] DEBUG - Request: [127.0.0.1:35250 (Loopback)] GET /library/changestamp (6 live) GZIP Signed-in Token (Duvrazh)
Jun 04, 2019 17:31:07.441 [0x7f6afb7fe700] DEBUG - Completed: [127.0.0.1:35250] 200 GET /library/changestamp (5 live) GZIP 0ms 467 bytes

==> Plex Media Scanner.log <==
Jun 04, 2019 17:31:07.441 [0x7fe22a503240] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/library/changestamp
Jun 04, 2019 17:31:07.441 [0x7fe22a503240] DEBUG - Updating metadata item (save) () with ID 24296
Jun 04, 2019 17:31:07.441 [0x7fe21b893700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/:/metadata/flushMetadataCounterCache

==> Plex Media Server.log <==
Jun 04, 2019 17:31:07.442 [0x7f6aa9ffb700] DEBUG - Request: [127.0.0.1:35252 (Loopback)] GET /:/metadata/flushMetadataCounterCache (5 live) GZIP Signed-in Token (Duvrazh)

==> Plex Media Scanner.log <==
Jun 04, 2019 17:31:07.442 [0x7fe21b893700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/:/metadata/flushMetadataCounterCache

==> Plex Media Server.log <==
Jun 04, 2019 17:31:07.442 [0x7f6afaffd700] DEBUG - Completed: [127.0.0.1:35252] 200 GET /:/metadata/flushMetadataCounterCache (5 live) GZIP 0ms 166 bytes

This is version 1.15.8.1163. I thought this version was subject to the database lock problems. I was waiting for it to fail before scripting up an overlayfs to ramdrive the database. It looks like I don’t have a need to. The only difference between before and now is that the filesystem for the OS was thin provisioned on the first one, thick provisioned with lazy zeroing on the current. That alone shouldn’t have any measurable impact on the operating system or its applications.

@ChuckPa - If you have thoughts on this since you’re familiar with the topic and have been such a big help, I very much welcome your input. What do you make of this? Was the database lock issued resolved between versions 1.15.4.994 and 1.15.8.1163?

33

To my knowledge, it’s not been fully resolved but there is one plausible explanation. It might be more ‘possible’ than ‘plausible’ but there are inherent delays using the remote. It might be; the latency induced, along with the single-threaded nature, is just enough to allow the active PMS threads to get into the DB and out before the next DB transaction occurs for the media.

Thoughts?

34

Hmmm… I’m going to have to take this to rclone forum and get more perspective. This time I had a Jellyfin server running the exact same remote services (quick and dirty) scanning at the same time. My error percentage on the API was less than 0.1%. Tomorrow I’ll make a post and see if I can get them to look at this thread and get some rclone experts to chime in with theories.

This one is mysterious. I’ll post back when I have more information from more knowledgeable individuals. In the meantime, hopefully the above posted rclone configuration helps out others who are sharing this issue.

Additionally, I’m going to make a public github repo for rclone and plex - and I’m going to test several variations of all the configuration parameters. I think it’s about time someone took that project on to find just where Plex breaks in this configuration style, which appears to me to be common. Anyways… Until then.

35

PS the DB is local, not living on the remote, although I had considered that. I wonder what results that would yield. Also going to test that. So many servers, so little time. :slight_smile:

36

Not that the DB is remote; The I/O wait which happens inherent with each ‘transaction’ (media file - DB pair)

37

I’d dig more into that with the experts but I don’t feel that’s an area we have much control over. So it’s potential that I got ‘lucky’ with this particular instance.

38

I agree which is why I said:

That’s Engineer-speak for “Dumb Luck happens here”

39

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.