Reply to thread

Message

<blockquote data-quote="RonD" data-source="post: 1223488" data-attributes="member: 117536">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<ol>
<li data-xf-list-type="ol">Start reading Recording file, 64 KB reads (length = 65536) to sequential offsets</li>
<li data-xf-list-type="ol">Continue 64 KB reads up to a 16 MB boundary (Offset: 16,711,680, Length: 65,536)</li>
<li data-xf-list-type="ol">Start doing 4 MB reads to sequential addresses (Offset: 16,777,216, Length: 4,194,304)</li>
<li data-xf-list-type="ol">Does 6 or more 4MB reads for 24 MB of data, details vary a bit for each file.</li>
<li data-xf-list-type="ol">Start seeing long 100+ millisec Duration times shortly after large 24 MB read requests are made</li>
</ol>See spoiler for details from CSV trace[SPOILER][code]starts with&nbsp; 636 millisec HDD spin-up delay, then sequential 64 KB reads8:40:57.1215057 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.6368185&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 0, Length: 65,5368:40:57.7720189 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0005106&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 65,536, Length: 65,5368:40:57.7720549 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0003979&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 65,536, Length: 65,536, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:57.7730468 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0000407&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 131,072, Length: 65,5368:40:57.7736207 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0261947&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 196,608, Length: 65,53664 KB Reads continue till 16 MB boundary8:40:58.1226438 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0000218&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 16,580,608, Length: 65,5368:40:58.1233155 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0000252&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 16,646,144, Length: 65,5368:40:58.1237763 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0000178&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 16,711,680, Length: 65,5368:40:58.1260088 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.1566643&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 16,777,216, Length: 4,194,3048:40:58.1270685 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.1124435&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 17,039,360, Length: 1,835,008, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:58.1271165 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.1538377&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 18,874,368, Length: 2,097,152, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:58.2836879 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0024029&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 20,971,520, Length: 4,194,3048:40:58.2871326 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0019399&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 25,165,824, Length: 4,194,3048:40:58.2903822 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0732815&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 29,360,128, Length: 4,194,3048:40:58.3646195 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0479808&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 33,554,432, Length: 4,194,3048:40:58.4135099 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0396833&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 37,748,736, Length: 4,194,3048:40:58.4567739 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.1452009&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,845,260, Length: 65,5368:40:58.4568549 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.1391075&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,844,160, Length: 69,632, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:58.6024014 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0008147&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,910,796, Length: 65,5368:40:58.6025145 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0006086&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,913,792, Length: 65,536, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:58.6039507 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0011364&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,976,332, Length: 65,5368:40:58.6042225 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0007211&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,394,979,328, Length: 61,440, I/O Flags: Non-cached, Paging I/O, Priority: Normal8:40:58.6056851 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0002831&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,395,041,868, Length: 65,5368:40:58.6065520 AM&nbsp; &nbsp; MediaPortal.exe&nbsp; &nbsp; 13932&nbsp; &nbsp; ReadFile&nbsp; &nbsp; 0.0000926&nbsp; &nbsp; K:\MePo1\recordings\KBCW-DT\Bay Area NightBeat\Bay Area NightBeat - 2017-05-30.ts&nbsp; &nbsp; SUCCESS&nbsp; &nbsp; Offset: 4,395,107,404, Length: 65,536[/code][/SPOILER]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 CommentsFor 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 &quot;Turn Off Drive after 0 minutes&quot; to disable HDD power management. The WD &quot;Blue Desktop&quot; 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.</blockquote>

[QUOTE="RonD, post: 1223488, member: 117536"] 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 [LIST=1] [*]Start reading Recording file, 64 KB reads (length = 65536) to sequential offsets [*]Continue 64 KB reads up to a 16 MB boundary (Offset: 16,711,680, Length: 65,536) [*]Start doing 4 MB reads to sequential addresses (Offset: 16,777,216, Length: 4,194,304) [*]Does 6 or more 4MB reads for 24 MB of data, details vary a bit for each file. [*]Start seeing long 100+ millisec Duration times shortly after large 24 MB read requests are made [/LIST] See spoiler for details from CSV trace [SPOILER] [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 [/code] [/SPOILER] 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. [/QUOTE]

Verification