Busy database lockout - PMS 1.10.0

server-windows

#1

This discussion was created from comments split from: Plex Crashing frequently for the past few months.


#2

@ChuckPA said:

@brndnkjns said:
ChuckPA, do you mind looking at my logs? I’m having a similar issue. Or is it bad form for me to hijack this thread? If so, I can start a new one. Thanks.

It's generally bad form however, in this case, what you're experiencing are hangs. The database reports at locked. I see you are running 1.10.1. I recommend you stop PMS, reboot the machine, reinstall the previous version (1.10.0) which is public and verify the same behavior.

Dec 09, 2017 13:52:59.858 [9568] DEBUG - Completed: [127.0.0.1:58586] 206 PUT /video/:/transcode/session/lrdj1p5h8ybuck2h023gnwmi/e8a381cc-d8ea-4a0b-87e0-5ea53f45e130/progress?progress=12.4&size=-22&remaining=65167&vdec_packets=25470&vdec_sw_ok=25460&vdec_hw_status=0 (14 live) 4ms 342 bytes
Dec 09, 2017 13:52:59.983 [5728] ERROR - Soci Exception handled: sqlite3_statement_backend::loadOne: database is locked
Dec 09, 2017 13:52:59.983 [9568] DEBUG - Completed: [192.168.1.43:41007] 500 GET /:/timeline?hasMDE=1&ratingKey=62337&key=%2Flibrary%2Fmetadata%2F62337&state=playing&playQueueItemID=29750&time=882532&duration=8595630 (14 live) TLS GZIP 67449ms 405 bytes (pipelined: 1)
Dec 09, 2017 13:52:59.983 [9568] DEBUG - Auth: authenticated user 1 as brndnkjns
Dec 09, 2017 13:52:59.983 [7692] DEBUG - Request: [192.168.1.43:41007 (Subnet)] GET /:/timeline?hasMDE=1&ratingKey=62337&key=%2Flibrary%2Fmetadata%2F62337&state=playing&playQueueItemID=29750&time=932537&duration=8595630 (14 live) TLS GZIP Signed-in Token (brndnkjns)
Dec 09, 2017 13:52:59.983 [7692] DEBUG - Client [zzjwlkwmqg0y2lunj9va8xgv] reporting timeline state playing, progress of 932537/8595630ms for guid=, ratingKey=62337 url=, key=/library/metadata/62337, containerKey=, metadataId=62337
Dec 09, 2017 13:53:00.421 [10072] DEBUG - Request: [127.0.0.1:58587 (Loopback)] PUT /video/:/transcode/session/lrdj1p5h8ybuck2h023gnwmi/e8a381cc-d8ea-4a0b-87e0-5ea53f45e130/progress?progress=12.4&size=-22&remaining=57949&vdec_packets=25471&vdec_sw_ok=25461&vdec_hw_status=0 (15 live) Signed-in Token (brndnkjns)
Dec 09, 2017 13:53:00.421 [9572] DEBUG - Completed: [127.0.0.1:58587] 206 PUT /video/:/transcode/session/lrdj1p5h8ybuck2h023gnwmi/e8a381cc-d8ea-4a0b-87e0-5ea53f45e130/progress?progress=12.4&size=-22&remaining=57949&vdec_packets=25471&vdec_sw_ok=25461&vdec_hw_status=0 (15 live) 2ms 342 bytes
Dec 09, 2017 13:53:00.983 [5728] DEBUG - Request: [127.0.0.1:58588 (Loopback)] PUT /video/:/transcode/session/lrdj1p5h8ybuck2h023gnwmi/e8a381cc-d8ea-4a0b-87e0-5ea53f45e130/progress?progress=12.4&size=-22&remaining=58977&vdec_packets=25473&vdec_sw_ok=25463&vdec_hw_status=0 (14 live) Signed-in Token (brndnkjns)
Dec 09, 2017 13:53:00.983 [9572] DEBUG - Completed: [127.0.0.1:58588] 206 PUT /video/:/transcode/session/lrdj1p5h8ybuck2h023gnwmi/e8a381cc-d8ea-4a0b-87e0-5ea53f45e130/progress?progress=12.4&size=-22&remaining=58977&vdec_packets=25473&vdec_sw_ok=25463&vdec_hw_status=0 (14 live) 2ms 342 bytes
Dec 09, 2017 13:53:01.077 [10460] WARN - Waited one whole second for a busy database.
Dec 09, 2017 13:53:01.202 [9612] WARN - Waited one whole second for a busy database.
Dec 09, 2017 13:53:01.280 [8172] WARN - Waited one whole second for a busy database.
Dec 09, 2017 13:53:01.546 [6156] DEBUG - Request: [127.0.0.1:58589 (Loopback)] PUT /video

@ChuckPA,

I downgraded to 1.10.0 as you suggested. I thought it had fixed the problem, but it may have caused a new one.

The server is accessible (unlike last time), but movies will not play. I've attached the logs. Any chance it's a new/different problem? Or do you think it's the same issue?

Logs attached.


#3

You're running on Windows. Something I just learned about windows.

Does your virus scanner scan the Plex data area? If it is, it can make the database lock.

If you can add an exception for %APPDATA%\PlexMediaServer Stop it from scanning the metadata area whenever PMS is trying to access it / write to it. It's probably triggering on PMS writing and going to back to scan it. Not good.

Do the same with the transcoder temp directory.


#4

@ChuckPA said:
You're running on Windows. Something I just learned about windows.

Does your virus scanner scan the Plex data area? If it is, it can make the database lock.

If you can add an exception for %APPDATA%\PlexMediaServer Stop it from scanning the metadata area whenever PMS is trying to access it / write to it. It's probably triggering on PMS writing and going to back to scan it. Not good.

Do the same with the transcoder temp directory.

Crap. I'm sorry. That's what I get for hijacking this thread. Were you talking to me or OP?

I just uploaded new logs with the most recent seize of my server. I don't have a virus scanner on my dedicated machine.

If you weren't talking to me, please ignore me.


#5

Now you're split out into your own thread.


#6

Just noticed this today. Thanks for the split.

The downgrade doesn't appear to have fixed things. I'm on 1.10.0 now. The problem has changed.

I don't have a virus scanner. Plex is responsive (unlike when I was on 1.10.1), but videos won't play.

Attached is the latest log. Is it the same error as before? Any chance the installation of PlexPy with the downgrade is causing this new problem?

Logs attached.


#7

let the logs finish uploading and a URL to show in the reply before you hit "Post Comment"


#8

Got it.

Logs should be attached now.

Thanks


#9

Thank you for the logs. Unfortunately this is well above my Windows skill level.

I'd like to ask @sa2000 or @OttoKerner to take a look

Dec 14, 2017 12:45:10.578 [7596] DEBUG - Completed: [192.168.1.24:59421] 200 GET /status/sessions (13 live) 10ms 7197 bytes (pipelined: 1)
Dec 14, 2017 12:45:10.859 [8768] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:12.531 [11428] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:12.609 [5840] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:12.671 [11940] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:14.203 [8768] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:15.874 [11428] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:15.953 [5840] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:16.015 [11940] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:17.546 [8768] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:19.093 [7596] DEBUG - Auth: authenticated user 1 as brndnkjns
Dec 14, 2017 12:45:19.093 [7592] DEBUG - Auth: authenticated user 1 as brndnkjns
Dec 14, 2017 12:45:19.093 [11360] DEBUG - Request: [192.168.1.24:59424 (Subnet)] GET /status/sessions (14 live) Signed-in Token (brndnkjns)
Dec 14, 2017 12:45:19.093 [6228] DEBUG - Request: [192.168.1.24:59425 (Subnet)] GET /status/sessions (13 live) Signed-in Token (brndnkjns)
Dec 14, 2017 12:45:19.093 [11360] DEBUG - [Now] Adding 1 sessions.
Dec 14, 2017 12:45:19.109 [6228] DEBUG - [Now] Adding 1 sessions.
Dec 14, 2017 12:45:19.109 [7596] DEBUG - Completed: [192.168.1.24:59424] 200 GET /status/sessions (13 live) 5ms 7197 bytes (pipelined: 1)
Dec 14, 2017 12:45:19.109 [7596] DEBUG - Completed: [192.168.1.24:59425] 200 GET /status/sessions (13 live) 6ms 7197 bytes (pipelined: 1)
Dec 14, 2017 12:45:19.218 [11428] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:19.296 [5840] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:19.359 [11940] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:20.890 [8768] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:22.562 [11428] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:22.640 [5840] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:22.703 [11940] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:24.234 [8768] WARN - Waited one whole second for a busy database.
Dec 14, 2017 12:45:24.468 [11940] ERROR - Soci Exception handled: sqlite3_statement_backend::loadOne: database is locked

#10

@ChuckPA said:
Thank you for the logs. Unfortunately this is well above my Windows skill level.

I'd like to ask @sa2000 or @OttoKerner to take a look

@sa2000 or @OttoKerner ? Any idea?


#11

Something is severely wrong.

  1. activate debug logging (not 'verbose'!)
  2. quit Plex Server
  3. wait 1 minute
  4. start Plex Server
  5. wait 5 minutes
  6. fetch log files and attach them here

Or inspect them yourself. Take a look at the Plex Media Server.log file and seek for messages about database corrupt or malformed.
If you find these, you may have to repair your database.
https://support.plex.tv/hc/en-us/articles/201100678-Repair-a-Corrupt-Database


#12

Thanks @OttoKerner

I did as you outlined. I've attached the logs. A few notes (not sure if they matter):
1. It doesn't hang immediately, but usually within 24 hours.
2. When I log into the PlexServer, the "spinning" circle showing scanning of photos is usually going... endlessly.

Thanks for the help.


#13

What is the largest number of photos you have in one folder/library?


#14

There are no signs of database corruption in your log. Good!

Is this NAS still in existence on your network?
If it's not, you should remove the reference to it from your DVR library

Dec 17, 2017 20:54:16.783 [9048] ERROR - Couldn't check for the existence of file \\diskstation\.grab: boost::filesystem::status: The network name cannot be found: "\\diskstation\.grab"

Something is not right about that address.
The host name is diskstation
but then there is supposed to follow a 'share' name
I don't think that .grab is a share name. This looks more like a folder name for Plex's DVR feature.
So this path is missing a share name.


#15

@OttoKerner said:
There are no signs of database corruption in your log. Good!

Is this NAS still in existence on your network?

Yes. The Plex Server is running on a dedicated machine with no files on it. It's pointing to a NAS at \diskstation

There is a folder for each file type.... Movies in \\diskstation\video\Movies for example.

@OttoKerner said:
Dec 17, 2017 20:54:16.783 [9048] ERROR - Couldn't check for the existence of file \diskstation.grab: boost::filesystem::status: The network name cannot be found: "\diskstation.grab"
``
Something is not right about that address.
The host name is
diskstation
but then there is supposed to follow a 'share' name
I don't think that
.grab` is a share name. This looks more like a folder name for Plex's DVR feature.
So this path is missing a share name.

I don't have the DVR set up. When I go to the Settings, DVR page, it gives me the option to set it up, which I have not done.

Any way to undo whatever is making the not-set-up-DVR portion go for that non existent 'share'?


#16

@OttoKerner said:
What is the largest number of photos you have in one folder/library?

maybe 2000?


#17

@brndnkjns said:
Yes. The Plex Server is running on a dedicated machine with no files on it. It’s pointing to a NAS at \diskstation

  1. WINS is sometimes unreliable. I’d change to the IP address of the NAS.
    (Make sure that your NAS always gets the same IP!)
    \\192.168.1.x\sharename\foldername

There is a folder for each file type… Movies in \\diskstation\video\Movies for example.

Good.

Any way to undo whatever is making the not-set-up-DVR portion go for that non existent ‘share’?

It is probably not of importance if you don’t use the DVR anyway.

  1. Settings - Server - Library - ’ Empty trash automatically after every scan’
    this should be always OFF with a networked media storage

  2. What type of a drive is your C: drive?
    I hope it is not a mobile USB hard disk which powers down its spindle aggressively. (Some USB drives do that unfortunately, in a mad attempt at saving power, completely independently from the Windows power settings.)

  3. For good measure, you should do this on all Windows computers which are either a Plex server or client:


#18

Thanks. I tried everything you suggested this morning. It had crashed by the afternoon. So I’ve attached the logs again from the most recent crash today.

I hate to call it a “crash”, because it’s more of a “hang”. I can access Plex Server through the browser, but nothing will play.

One more question… any chance old busted sync jobs could be causing the problem? I don’t see any in my queue, but a sync job I tried from remote a few weeks ago happened around the same time.

@OttoKerner said:

  1. WINS is sometimes unreliable. I’d change to the IP address of the NAS.
    (Make sure that your NAS always gets the same IP!)
    \\192.168.1.x\sharename\foldername

Done

  1. Settings - Server - Library - ’ Empty trash automatically after every scan’
    this should be always OFF with a networked media storage

Done

  1. What type of a drive is your C: drive?
    I hope it is not a mobile USB hard disk which powers down its spindle aggressively. (Some USB drives do that unfortunately, in a mad attempt at saving power, completely independently from the Windows power settings.)

Not a USB drive. Internal.

  1. For good measure, you should do this on all Windows computers which are either a Plex server or client:

Done


#19

Old sync jobs get disabled after several months that the device hasn't been 'seen'.
You could however delete it, to be sure.

Are you using an anti virus software on that machine?
If so, create an exemption for the Plex data folder in its preferences. This is also possible in the default 'Windows Defender'.

How much RAM is in that machine?
How much space is left on C: ?


#20

@OttoKerner said:
Old sync jobs get disabled after several months that the device hasn't been 'seen'.
You could however delete it, to be sure.

Just logged into all devices and deleted any sync'd content.

Are you using an anti virus software on that machine?
If so, create an exemption for the Plex data folder in its preferences. This is also possible in the default 'Windows Defender'.

No anti-virus

How much RAM is in that machine?

8GB Ram

How much space is left on C: ?

46GB Free

On a side note, I just deleted the Photos (the one that seemed to be constantly scanning).