MP1.16 Remote Client Unable to Play: B43534E1 error watching Recorded TV (3 Viewers)

[Owlsroost]

Owlsroost, are you thinking to include the increased RTSP timeout in a future version of MP?

Yes - I'll create a Jira for it.

As this is a simple change, I think we can treat this as a 'bug' and hence propose it for inclusion in MP 1.17 final (if that is OK with you?).

EDIT - Jira: [MP1-4870] TsReader RTSP request timeout is too short in some situations - MediaPortal JIRA

 

[mm1352000]

if that is OK with you?

Honestly, I view it as more of an issue with Ron's setup than a bug/issue in/with MP. As such, if at all possible I'd prefer to figure out what's going on with Ron's setup. I note that so far nobody else seems to have reported a problem with the current timeouts. Trading off an increased timeout for one person... well, it just doesn't feel right. On the other hand I do realise it may not be possible to definitively confirm what's going on, and so increasing the timeout may be the only pragmatic approach.

 

[RonD]

So far no problems (1 day) with TsReader_4.2.2.35.zip

Honestly, I view it as more of an issue with Ron's setup than a bug/issue in/with MP.

Not sure what @mm1352000 is looking for, but setup ProcessMonitor to track Drive-K (HDD WD30EZRZ) during MP1.16 startup. Drive-K was idle overnight and trace shows TV-Series doing recording folder scan, finding about 15 recordings that are not in database and doing a MediaInfo scan on the files. Most of these recordings are things like local TV news that are not on Online TV Database - An open directory of television shows for HTPC software so they never get added to TV-Series. Happens everytime I start MP, feature not a bug.

ProcessMonitor (csv/zip) file has the following for about 7200 disk reads. During MP startup the initial reads are to “The Ten O'clock News on KTVU Fox 2”, all initial reads must be hitting Drive-K internal ram-cache and 1st 400 reads show Read Durations less than 0.1 millisec, then the next disk read shows Duration = 636 millisec. Assume this is 1st real HDD access and needs to spin up the HDD. After this see fast disk read times less than 0.1 millisec, and others that are 15 to 20 millisec. Assume the longer reads are seek to nearby cylinder and disk spin time. BUT also see longer read durations, up to 160 millisec, assume these are longer seeks. Attached pictures show longest 100 Disk Read Durations and a Disk Duration vs Time view. In the 2nd set if pictures I set max Time = 200 millisec to ignore long 636 millisec spin up time. My guess is the longer Durations are long seeks to next Recording on Drive-K.

A high level histogram view shows the following for the slowest 100 Read Durations
160 to 92 millisec, reads 1 to 25 slowest
92 to 40 millisec, reads 26 to 50, next slowest
40 to 19 millisec, reads 51 to 75
19 to 13 millisec, reads 76 to 100, probably typical short seek spin times

In the 80s, 90s I designed and built department and database server computers, and surprised to access, seek times over 100 millisec. But servers were using 14 inch to 8 inch drives with capacities from 470 MB to 1-2 GB. Still sort of amazing a 3.5 inch drive has 3000 GB, so maybe they are a bit slower. Fujitsu Eagle Fujitsu Eagle - Wikipedia took 2 people to install a 470 MB drive in a rack.

So not sure what to say on my Drive-K recordings, feature or bug? But on this WD “Blue” 5400 rpm HDD, spin up seems to take 600 millisec and some drive seeks can take 100 to 160 millisec. WD Blue Desktop | Western Digital (WD)

 

[RonD]

Looked into what causes the 100+ millisec read delays. Looks like long delays are caused when MediaPortal.exe starts doing back to back 4 MB reads, this may be more of MediaInfo or something in TV-Series. General flow for each Recording file does the following

1. Start reading Recording file, 64 KB reads (length = 65536) to sequential offsets
2. Continue 64 KB reads up to a 16 MB boundary (Offset: 16,711,680, Length: 65,536)
3. Start doing 4 MB reads to sequential addresses (Offset: 16,777,216, Length: 4,194,304)
4. Does 6 or more 4MB reads for 24 MB of data, details vary a bit for each file.
5. Start seeing long 100+ millisec Duration times shortly after large 24 MB read requests are made

See spoiler for details from CSV trace

Spoiler

starts with  636 millisec HDD spin-up delay, then sequential 64 KB reads

8:40:57.1215057 AM    MediaPortal.exe    13932    ReadFile    0.6368185    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 0, Length: 65,536
8:40:57.7720189 AM    MediaPortal.exe    13932    ReadFile    0.0005106    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 65,536, Length: 65,536
8:40:57.7720549 AM    MediaPortal.exe    13932    ReadFile    0.0003979    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 65,536, Length: 65,536, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:57.7730468 AM    MediaPortal.exe    13932    ReadFile    0.0000407    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 131,072, Length: 65,536
8:40:57.7736207 AM    MediaPortal.exe    13932    ReadFile    0.0261947    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 196,608, Length: 65,536

64 KB Reads continue till 16 MB boundary

8:40:58.1226438 AM    MediaPortal.exe    13932    ReadFile    0.0000218    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 16,580,608, Length: 65,536
8:40:58.1233155 AM    MediaPortal.exe    13932    ReadFile    0.0000252    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 16,646,144, Length: 65,536
8:40:58.1237763 AM    MediaPortal.exe    13932    ReadFile    0.0000178    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 16,711,680, Length: 65,536
8:40:58.1260088 AM    MediaPortal.exe    13932    ReadFile    0.1566643    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 16,777,216, Length: 4,194,304
8:40:58.1270685 AM    MediaPortal.exe    13932    ReadFile    0.1124435    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 17,039,360, Length: 1,835,008, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:58.1271165 AM    MediaPortal.exe    13932    ReadFile    0.1538377    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 18,874,368, Length: 2,097,152, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:58.2836879 AM    MediaPortal.exe    13932    ReadFile    0.0024029    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 20,971,520, Length: 4,194,304
8:40:58.2871326 AM    MediaPortal.exe    13932    ReadFile    0.0019399    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 25,165,824, Length: 4,194,304
8:40:58.2903822 AM    MediaPortal.exe    13932    ReadFile    0.0732815    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 29,360,128, Length: 4,194,304
8:40:58.3646195 AM    MediaPortal.exe    13932    ReadFile    0.0479808    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 33,554,432, Length: 4,194,304
8:40:58.4135099 AM    MediaPortal.exe    13932    ReadFile    0.0396833    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 37,748,736, Length: 4,194,304
8:40:58.4567739 AM    MediaPortal.exe    13932    ReadFile    0.1452009    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,845,260, Length: 65,536
8:40:58.4568549 AM    MediaPortal.exe    13932    ReadFile    0.1391075    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,844,160, Length: 69,632, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:58.6024014 AM    MediaPortal.exe    13932    ReadFile    0.0008147    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,910,796, Length: 65,536
8:40:58.6025145 AM    MediaPortal.exe    13932    ReadFile    0.0006086    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,913,792, Length: 65,536, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:58.6039507 AM    MediaPortal.exe    13932    ReadFile    0.0011364    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,976,332, Length: 65,536
8:40:58.6042225 AM    MediaPortal.exe    13932    ReadFile    0.0007211    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,394,979,328, Length: 61,440, I/O Flags: Non-cached, Paging I/O, Priority: Normal
8:40:58.6056851 AM    MediaPortal.exe    13932    ReadFile    0.0002831    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,395,041,868, Length: 65,536
8:40:58.6065520 AM    MediaPortal.exe    13932    ReadFile    0.0000926    K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts    SUCCESS    Offset: 4,395,107,404, Length: 65,536

Did another ProcessMonitor trace, this time keeping all data, 170000 row CSV file, see same behavior. For what it is worth this shows windows is doing IRP_MJ_READ and FASTIO_READ. Not sure what is going on inside windows, guess the code is doing buffered read optimizations for large file accesses, but has side effect of blocking other read operations for 100+ millisec waiting for 16 to 24 MB of read data in buffers.

EDITED Comments

For 100+ millisec read delays, nothing strange is going on at the HDD level, just windows strange stuff. Maybe Windows programmer-dude(ttes) have a better idea.

For 600+ millisec HDD drive spin-up delay, WIN-10 power management is set for "Turn Off Drive after 0 minutes" to disable HDD power management. The WD "Blue Desktop" HDD ignores this setting and does internal HDD turn on/off and causes 600+ millisec delay.

Attached zip has csv examples for both ProcessMonitor traces. Just 20 to 30 lines showing 64 KB reads and start of 4 MB reads.

 

[Owlsroost]

Yes, Windows will perform 'read ahead' caching if it thinks the file read access pattern is basically sequential (and you don't open the file in 'random access' mode). Basically Windows tries to adapt the caching behaviour to the access pattern it's seeing from the software (as far as I've ever managed to find out. So after it's seen the series of sequential 64K reads (from MP) it assumes that is the access pattern, and starts to read-ahead and cache the data.

I would expect (for a static file) that the data the duration measurement is reading (the very beginning and end of the flle) would be cached and hence not cause actual disk reads most of the time - certainly for my own single-seat system that is what seems to happen (I've had debug code in TsReader to measure the duration access times and they are normally very short).

Here are some links to info about file caching behaviour in Windows:

How do FILE_FLAG_SEQUENTIAL_SCAN and FILE_FLAG_RANDOM_ACCESS affect how the operating system treats my file?

What Is The Difference Between FileFlags.Random (FILE_FLAG_RANDOM_ACCESS) And FileFlags.SequentialScan (FILE_FLAG_SEQUENTIAL_SCAN)?

(In TsReader and StreamingServer, timeshift files are opened in FILE_FLAG_RANDOM_ACCESS mode, and other files in FILE_FLAG_SEQUENTIAL_SCAN mode).

 

[Owlsroost]

Hi Ron,

If you feel like analysing the disk activity again, attached are two versions of StreamingServer.dll as an experiment:

'v1.1.7_no_seq' does not set the FILE_FLAG_SEQUENTIAL_SCAN flag when opening recording files i.e. it lets Windows decide how to cache the file data for both the data reads and duration measurement reads. No changes to handling timeshift files.

'v1.1.8_random_read_duration' sets the FILE_FLAG_RANDOM_ACCESS flag when opening recording files for duration measurement reads only. Otherwise it's the same as the 'v1.1.7_no_seq' version.

It may be that you don't notice any difference in actual behaviour (since these flags are only hints to the Windows caching logic).

 

[RonD]

Tried all 3 StreamingServer_dll files, v1.1.5 from the other thread and both v1.1.7 and v.1.18 from this thread. Zipfile has LibreOffice “.ods” file with trace info. 1 sheet per test. I can save/upload a excel “.xls” file if that is better. But bottom line is no real difference with any of the StreamingServer_dll, suspect the "prefetch" activity is part of MediaInfo.

For testing I used different episodes of the same show so each time I watched video it would be 1st access to that recording/file. All recordings are 1920-1080i, 62 minute, 3720 sec, the files are about 7150 MB, so about 1.9 MB/sec when watching video. Trace is about 3 minutes for each file. All 3 traces show about same story, the various StreamingServer seem to work the same. All 3 traces show 2 long 0.5+ sec delays. See picture.

Looking at 1 trace in detail seems like there are 2 different phases, from v1.1.7_no_seq, the other 2 traces are similar used color to highlight interesting rows in all 3 traces.

Phase 1
row 11, 2:56:33.1070574 PM, duration 0.5341599, mediaportal start reading 16 MB at Offset 0, sequential 64 to 128 KB
row 66, 2:56:33.8842895 PM, finish reading 16 MB at offset Offset: 16,711,680

row 669, 2:56:33.8859023 PM, start ~40 MB prefetch in 2 to 4 MB blocks at offset Offset: 16,777,216
there are a few 0.1 sec duration reads after the prefetch starts

row 691, 2:56:34.1521507 PM, mediaportal skips to Offset: 7,311,692,144 start reading 16 MB
row 1342, 2:56:34.4757121 PM, finish reading at Offset: 7,328,403,824

Phase 2
row 1365, 2:56:34.5504293 PM, start reading at Offset 0, sequential 64 to 128 KB
row 1786, 2:57:01.5046248 PM, long duration 0.5208976 delay, Offset: 50,331,648
in the middle of sequential 128 KB reads no obvious signs of other activity, prefetch
Nothing else interesting after the delays, just more sequential reads

My guess is Phase 1 is MediaInfo scanning recording to identify how to stream the video. Phase 2 is streamingserver reading/streaming video to "watch"

No Idea what causes the 2 sets of long 0.5+ sec delays in each file. There is one 0.5+ sec delay in Phase 1 and one 0.5 sec delay in Phase 2. The long delay times are

V1.1.5
row 78, 3:07:24.3155881 PM, Offset: 2,031,616, Length: 65,536
row 1751, 3:07:52.9099328 PM, Offset: 50,331,648, Length: 131,072
v1.1.7
row 11, 2:56:33.1070574 PM, Offset: 0, Length: 65,536
row 1786, 2:57:01.5046248 PM, Offset: 50,331,648, Length: 131,072
v1.1.8
row 86, 3:02:01.4575030 PM, Offset: 2,293,760, Length: 65,536
row 1805, 3:02:31.6878231 PM, Offset: 54,657,024, Length: 262,144

 

[Owlsroost]

Hi Ron,

Thanks for the testing.

Streaming Server (and TsReader) don't read large chunks of data - they read data from disk 'little and often' in 64KB to 256KB chunks, so I agree that the large reads are probably Windows read-ahead caching or something else (like Mediainfo, although I don't know what it's used for in TV Server).

 

[mm1352000]

My understanding is that the only use of MediaInfo in TV Server is in the thumbnailer. Corrupt/invalid recordings used to hang the thumbnailer. Now the thumbnailer runs recordings through MediaInfo first. If the recording duration as detected/calculated by MediaInfo is greater than zero then the thumbnailer proceeds with its attempt to generate a thumbnail. All of this should happen immediately after a recording completes, and obviously thumbnail generation only needs to happen once (...unless thumbnails are deleted manually, in which case they're regenerated on TV Server startup).

Again, this is all to the best of my knowledge/memory. I could be mistaken and/or missing details.

If either of you think the thumbnailer could be a factor, testing with it disabled would be an obvious thing to try. Easy to disable. Untick "autocreate thumbs":
Recording - MediaPortal 1 - MediaPortal Wiki