PMS 1.24.3.5033 database locked

Plex Media Server
1

Im running PMS 1.24.3.5033 and Im getting the DB locked and busy database warnings/errors in the logs. My Plex DB is located on a RAID1 of Toshiba Enterprise SAS 12G SSD. Resource monitor shows disk queue length never goes above 0.01 and response time never goes above 1ms. I see that there was issues with an earlier version of PMS, but Im seeing the same issue with the most recent version. I have done the usual Plex dance. Restart service, clean bundles, optimized DB.

Oct 05, 2021 09:47:20.505 [24424] WARN - SLOW QUERY: It took 328.125000 ms to retrieve 0 items.
Oct 05, 2021 09:47:20.562 [16136] WARN - Waited one whole second for a busy database.
Oct 05, 2021 09:47:20.748 [24424] WARN - SLOW QUERY: It took 328.125000 ms to retrieve 0 items.
Oct 05, 2021 09:47:21.256 [24424] WARN - SLOW QUERY: It took 375.000000 ms to retrieve 0 items.
Oct 05, 2021 09:47:21.304 [17908] WARN - Waited one whole second for a busy database.
Oct 05, 2021 09:47:22.404 [17908] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 05, 2021 09:47:22.760 [24424] WARN - SLOW QUERY: It took 328.125000 ms to retrieve 0 items.
Oct 05, 2021 09:47:22.977 [16136] WARN - Waited one whole second for a busy database.
Oct 05, 2021 09:47:23.306 [24424] WARN - DVR:NewSchedule: Couldn't schedule recording (error: The recording conflicts with other recordings).
Oct 05, 2021 09:47:23.307 [24424] WARN - DVR:NewSchedule: Couldn't schedule recording (error: The recording conflicts with other recordings).
Oct 05, 2021 09:47:23.766 [17908] WARN - Waited one whole second for a busy database.
Oct 05, 2021 09:47:24.420 [24424] WARN - Waited one whole second for a busy database.
Oct 05, 2021 09:47:24.865 [17908] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 05, 2021 09:47:25.014 [20564] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 05, 2021 09:47:25.014 [20564] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6aef5c8d56d002efdd09d
Oct 05, 2021 09:47:25.014 [20564] ERROR - Subscription: Error refreshing sub: No container found
Oct 05, 2021 09:47:25.020 [11936] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 05, 2021 09:47:25.020 [14076] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 05, 2021 09:47:25.020 [14076] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6abc81a65df002dd592c7
Oct 05, 2021 09:47:25.020 [11936] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6ad18678e02002ec5a7df
Oct 05, 2021 09:47:25.020 [14076] ERROR - Subscription: Error refreshing sub: No container found
Oct 05, 2021 09:47:25.020 [11936] ERROR - Subscription: Error refreshing sub: No container found
Oct 05, 2021 09:47:25.049 [11936] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 05, 2021 09:47:25.049 [11936] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6ad8af21710002d6c17f2
Oct 05, 2021 09:47:25.049 [11936] ERROR - Subscription: Error refreshing sub: No container found
Oct 05, 2021 09:47:25.116 [17908] WARN - Took too long (24.281250 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 05, 2021 09:47:25.116 [17908] WARN - Transaction that was running was started on thread 17908 at ..\Library\MetadataItem.cpp:1122
Oct 05, 2021 09:47:25.126 [9700] WARN - Took too long (15.343750 seconds) to start a transaction on ..\Statistics\StatisticsManager.cpp:249
Oct 05, 2021 09:47:25.126 [9700] WARN - Transaction that was running was started on thread 17908 at ..\Library\MetadataItem.cpp:1122
Oct 05, 2021 09:47:25.137 [16136] WARN - Took too long (0.625000 seconds) to start a transaction on ..\Library\MetadataCollection.cpp:333
Oct 05, 2021 09:47:25.137 [16136] WARN - Transaction that was running was started on thread 9700 at ..\Statistics\StatisticsManager.cpp:249

MODERATOR EDIT: Formatting

2 
Oct 06, 2021 08:42:08.019 [8536] WARN - DVR:NewSchedule: Couldn't schedule recording (error: The recording conflicts with other recordings).
Oct 06, 2021 08:42:23.499 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:42:23.499 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:42:52.859 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:42:52.860 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:43:22.816 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:43:22.817 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:43:49.539 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:43:49.540 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:44:12.628 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:44:12.628 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:44:37.693 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:44:37.693 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:44:59.802 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:00.900 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:02.260 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:03.365 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:04.156 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:04.156 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:04.734 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:05.834 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:06.669 [9768] WARN - Took too long (8.093750 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 08:45:06.669 [9768] WARN - Transaction that was running was started on thread 9768 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 08:45:21.338 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:22.438 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:23.797 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:24.896 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:26.253 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:27.352 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:27.702 [9768] WARN - Took too long (7.500000 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 08:45:27.702 [9768] WARN - Transaction that was running was started on thread 9768 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 08:45:30.916 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:30.916 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:41.370 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:42.470 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:43.829 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:44.933 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 08:45:46.301 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:45:47.312 [9768] WARN - Took too long (7.062500 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 08:45:47.312 [9768] WARN - Transaction that was running was started on thread 9768 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 08:45:58.338 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:58.339 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:45:59.784 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:46:00.890 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 08:46:02.250 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:46:03.349 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 08:46:04.710 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:46:05.810 [9768] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 08:46:07.175 [9768] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:46:08.238 [9768] WARN - Took too long (9.500000 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 08:46:08.238 [9768] WARN - Transaction that was running was started on thread 9768 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 08:46:23.495 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:46:23.496 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:46:46.714 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:46:46.714 [6400] WARN - MDE: unable to find a working transcode profile for video stream
Oct 06, 2021 08:57:36.249 [18028] WARN - NAT: PMP, got an error: NATPMP_ERR_RECVFROM.
Oct 06, 2021 08:57:39.250 [18028] ERROR - Error issuing curl_easy_perform(handle): 28
Oct 06, 2021 08:59:58.820 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 08:59:59.919 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:01.280 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:02.380 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:03.740 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:04.839 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:05.090 [20740] WARN - Took too long (7.312500 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 09:00:05.090 [20740] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 09:00:16.274 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:17.374 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:18.742 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:19.842 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:21.203 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:22.303 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:23.248 [20740] WARN - Took too long (8.203125 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 09:00:23.248 [20740] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 09:00:23.252 [26068] WARN - Took too long (3.343750 seconds) to start a transaction on ..\Statistics\StatisticsManager.cpp:249
Oct 06, 2021 09:00:23.252 [26068] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 09:00:34.080 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:35.179 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:36.538 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:37.635 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:38.996 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:40.094 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=3): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:40.487 [20740] WARN - Took too long (7.500000 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 09:00:40.487 [20740] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 09:00:51.118 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:52.217 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=1): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:53.581 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:54.681 [20740] ERROR - Failed to begin transaction (..\Library\MetadataItemClustering.cpp:69) (tries=2): Cannot begin transaction. database is locked
Oct 06, 2021 09:00:56.039 [20740] WARN - Waited one whole second for a busy database.
Oct 06, 2021 09:00:56.842 [20740] WARN - Took too long (6.953125 seconds) to start a transaction on ..\Library\MetadataItemClustering.cpp:69
Oct 06, 2021 09:00:56.842 [20740] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122
Oct 06, 2021 09:00:56.848 [24808] WARN - Took too long (3.609375 seconds) to start a transaction on ..\Statistics\StatisticsManager.cpp:249
Oct 06, 2021 09:00:56.848 [24808] WARN - Transaction that was running was started on thread 20740 at ..\Library\MetadataItem.cpp:1122

MODERATOR EDIT: Formatting

3

@adamesslinger

I have moved your posts here.

The other thread was SOLVED.

Please turn DEBUG logging back on.

I also ask you to make certain the database has been optimized.

Lastly, Please update to 1.24.4 PMS. There were some issues in 1.24.3.5033.

4

is 1.24.4 a beta? I don’t see an update available. I’m set on public releases channel

5 
1.24.4.5081-e362dc1ee

September 24, 2021

PlexPass downloads

6

Yes, it’s the beta channel build right now.

7

it appears that 1.24.4.5081 solved the slow query and locking issue.

On a side note…are these normal or do I have a DB schema issue?

Oct 06, 2021 11:57:23.226 [9476] WARN - QueryParser: Invalid field ‘contentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.226 [10860] WARN - QueryParser: Invalid field ‘contentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.227 [9476] WARN - QueryParser: Invalid field ‘pinnedContentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.227 [10860] WARN - QueryParser: Invalid field ‘pinnedContentDirectoryID’ found, ignoring
Oct 06, 2021 11:57:23.230 [8172] WARN - QueryParser: Invalid field ‘sectionID’ found, ignoring.
Oct 06, 2021 11:57:23.230 [9884] WARN - QueryParser: Invalid field ‘contentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.230 [9884] WARN - QueryParser: Invalid field ‘pinnedContentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.230 [8172] WARN - QueryParser: Invalid field ‘contentDirectoryID’ found, ignoring.
Oct 06, 2021 11:57:23.230 [8172] WARN - QueryParser: Invalid field ‘pinnedContentDirectoryID’ found, ignoring.

8 
Oct 06, 2021 13:01:20.400 [9864] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-01878.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:01:22.935 [11292] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:01:25.784 [13900] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:01:35.224 [13532] INFO - Library section 4 (TV Shows) will be updated because of a change in "O:\TVShows\Buying the Beach (2014)\Season 01\Buying the Beach (2014) - S01E01 - Island Fever.log"
Oct 06, 2021 13:01:50.284 [13900] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-01908.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:02:23.052 [10772] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:02:26.774 [9896] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:02:34.342 [13900] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-01952.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:03:17.357 [14232] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-01995.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:03:22.954 [13900] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:03:28.383 [9864] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:04:09.479 [14232] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02047.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:04:22.936 [9864] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:04:29.621 [9864] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:04:34.296 [9896] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02072.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:05:23.231 [14232] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:05:30.989 [11292] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:05:55.318 [11292] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02153.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:06:22.864 [9896] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:06:32.068 [11292] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:07:08.364 [9896] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02226.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:07:23.174 [13900] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:07:32.393 [13900] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02250.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:07:33.479 [9896] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:07:58.321 [11292] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02276.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:08:22.959 [14232] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:08:34.587 [14232] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:08:38.319 [14232] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02316.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:09:22.895 [10772] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:09:36.131 [10772] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:10:09.384 [9896] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02407.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:10:22.947 [9896] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:10:30.335 [13900] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02428.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:10:37.275 [13900] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:11:03.284 [10772] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02461.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:11:22.934 [10772] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:11:38.647 [14232] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
Oct 06, 2021 13:12:10.349 [13900] ERROR - Caught exception trying to stream file: P:\PlexData\Plex Media Server\Transcode\Transcode\Sessions\plex-transcode-e57cf952-ef0b-4873-92b5-1aca5bca6ac2\media-02528.ts: write: A request to send or receive data was disallowed because the socket had already been shut down in that direction with a previous shutdown call
Oct 06, 2021 13:12:22.912 [11292] WARN - Caught exception trying to convert extra data attribute 'originallyAvailableAt' with type 1 and value '2016-08-25' ~ bad lexical cast: source type value could not be interpreted as target
9

@adamesslinger

Would you please download and attach the entire logs ZIP file?

Pasting these snippets in the post is not productive.

Those invalid fields are Engineering work in progress.

10

Plex Media Server.zip (155.5 KB)

log attached

11

did you want the whole logs directory zipped up or just the most recent log? I attached just the most recent log

12

Plex Media Server.zip (539.4 KB)

after reviewing the logs further I can see that right after startup the logs complained about waiting on the DB/locking. Since then things seem better but I do occasionally see things like this:

Oct 07, 2021 08:07:43.834 [12000] WARN - Held transaction for too long (…\Library\MetadataCollection.cpp:507): 0.187500 seconds

Oct 07, 2021 08:06:58.336 [11656] WARN - Held transaction for too long (…\Library\MetadataItem.cpp:1126): 0.125000 seconds
Oct 07, 2021 08:06:58.349 [4048] WARN - Held transaction for too long (…\Library\MetadataItem.cpp:1126): 0.140625 seconds
Oct 07, 2021 08:06:58.365 [11656] WARN - Held transaction for too long (…\Library\MetadataItem.cpp:7178): 0.125000 seconds

Oct 07, 2021 08:06:58.201 [14228] WARN - Held transaction for too long (…\Library\MetadataCollection.cpp:507): 0.343750 seconds
Oct 07, 2021 08:06:58.210 [11656] WARN - Held transaction for too long (…\Library\MetadataItem.cpp:7178): 0.109375 seconds

attached is the latest log file.

13

@adamesslinger

  1. Please turn DEBUG logging back on. I can’t see what it’s doing without.

  2. DEBUG is the default.

  3. Log size is fixed. nothing gained by turning it off.

  4. Recreate and reattach logs ZIP (the whole set)

Be advised: You’re asking me about Windows. I don’t have anything Windows here. My support might be limited.

DB locked is usually I/O related, and, AFAIK on windows , fragmentation driven.

14

here ya goLogs.zip (22.0 MB)

15

thanks.

There is nothing directly in the most recent log

However, this:

Oct 06, 2021 11:39:25.014 [10996] WARN - SLOW QUERY: It took 500.000000 ms to retrieve 0 items.
Oct 06, 2021 11:39:25.039 [10996] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.039 [10996] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F601051f0e35722002c422345
Oct 06, 2021 11:39:25.039 [10996] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.064 [10992] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.205 [10992] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.369 [10996] WARN - SLOW QUERY: It took 421.875000 ms to retrieve 0 items.
Oct 06, 2021 11:39:25.448 [11000] WARN - SLOW QUERY: It took 421.875000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.487 [11004] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.487 [11004] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6966e9f0bc5002dbe7e14
Oct 06, 2021 11:39:25.487 [11004] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.501 [11004] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.501 [11004] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6a84a336b43002e0b7ad7
Oct 06, 2021 11:39:25.501 [11004] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.594 [10996] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.594 [10996] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6ac1375bdc2002e9e49a7
Oct 06, 2021 11:39:25.594 [10996] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.784 [11004] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 0 items.
Oct 06, 2021 11:39:25.784 [11000] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.845 [10992] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.862 [10992] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.862 [10992] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6ade41f0c59002e34682e
Oct 06, 2021 11:39:25.862 [10992] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.875 [10992] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.875 [10992] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6a81a6b022a002d700851
Oct 06, 2021 11:39:25.875 [10992] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.885 [10996] WARN - SLOW QUERY: It took 453.125000 ms to retrieve 0 items.
Oct 06, 2021 11:39:25.888 [10992] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:25.888 [10992] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F5fc6ac81b823d4002d763303
Oct 06, 2021 11:39:25.888 [10992] ERROR - Subscription: Error refreshing sub: No container found
Oct 06, 2021 11:39:25.897 [11000] WARN - SLOW QUERY: It took 453.125000 ms to retrieve 1 items.
Oct 06, 2021 11:39:25.957 [11000] WARN - SLOW QUERY: It took 250.000000 ms to retrieve 1 items.
Oct 06, 2021 11:39:26.164 [11004] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 1 items.
Oct 06, 2021 11:39:26.471 [11000] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 1 items.
Oct 06, 2021 11:39:26.680 [10992] WARN - SLOW QUERY: It took 437.500000 ms to retrieve 1 items.
Oct 06, 2021 11:39:26.732 [11004] ERROR - PlexClient::downloadContainer: expected MediaContainer element, found html
Oct 06, 2021 11:39:26.732 [11004] WARN - Subscription: No container available for /tv.plex.providers.epg.cloud:24/metadata/plex%3A%2F%2Fshow%2F606f2af5af97d0002de7beea
Oct 06, 2021 11:39:26.732 [11004] ERROR - Subscription: Error refreshing sub: No container found

is just a database in need of optimizing. (scheduled tasks and Manually now).
This will cause locked db because of contention waiting.

I see a lot of scanning activity. Are you adding a new library section?

16

I did a repair on the DB yesterday, using the method from the support article. Plex is already set to optimize database every week. I have new content coming in about every 30 minutes to existing libraries, but no new libraries being added.

image

I have Plex set to only do a partial scan when changes are detected.

image

17

I just did a clean bundles, then optimize database, then added 6 TV episodes
Plex Media Server Logs_2021-10-07_11-04-59.zip (2.8 MB)

18

That looks like a xeon? Which one please?

Asking because some xeons, in spite of their total passmark score, dont do well because the per-thread speed is low. ( Passmarks / Number of threads ). When that number is under 1000, it’s going to be sluggish and this type of performance problem will happen ( Each DB access is single-threaded – which is why a DB lock exists )

Couple a large DB (size of the com.plexapp.plugins.library.db) with the per-thread speed and you have a great CPU behave no better than a NAS CPU

19

I have a Dell PowerEdge R510 that has (2) Intel L5640. When I lookup the Passmark score it shows 4591

20

I haven’t been getting the DB locks but I do still see the slow query and held transaction to long … I found another thread where lots of users are complaining about this issue with an older version of PMS and there seems to be 2 fixes that I wonder if are still valid.1

  1. increase the SQLLite cache_size mine is current set to -2000
  2. Delete everything in the statistics tables