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

Owlsroost

Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    Last edited:

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    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

    Test Group
  • Team MediaPortal
  • December 20, 2011
    911
    278
    SillyValley CA
    Home Country
    United States of America United States of America
    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)
     

    Attachments

    • DiskReadSorted.PNG
      DiskReadSorted.PNG
      15.2 KB
    • DiskReadSorted200.PNG
      DiskReadSorted200.PNG
      14.4 KB
    • DiskReadTime.PNG
      DiskReadTime.PNG
      15 KB
    • DiskReadTime200.PNG
      DiskReadTime200.PNG
      22 KB

    RonD

    Test Group
  • Team MediaPortal
  • December 20, 2011
    911
    278
    SillyValley CA
    Home Country
    United States of America United States of America
    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
    Code:
    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.
     

    Attachments

    • MP_Startup.zip
      4.6 KB
    Last edited:

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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).
     
    Last edited:

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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).
     

    Attachments

    • StreamingServer_dll_v1.1.7_no_seq.zip
      82.1 KB
    • StreamingServer_dll_v1.1.8_random_read_duration.zip
      82.1 KB

    RonD

    Test Group
  • Team MediaPortal
  • December 20, 2011
    911
    278
    SillyValley CA
    Home Country
    United States of America United States of America
    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
     

    Attachments

    • streamingserver1.PNG
      streamingserver1.PNG
      38.9 KB
    • StreamingServerV1.zip
      1.4 MB
    Last edited:

    Owlsroost

    Retired Team Member
  • Premium Supporter
  • October 28, 2008
    5,540
    5,038
    Cambridge
    Home Country
    United Kingdom United Kingdom
    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

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    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
     

    Users who are viewing this thread

    Top Bottom