id summary reporter owner description type status priority milestone component version severity resolution keywords cc mlocked 9864 RingBuffer locking problem Jim Stichnoth danielk "There is a RingBuffer locking related issue that causes long delays in loading ISO videos with several titles using storage groups. (This is the same as issue 2 in #9854.) See the attached frontend log using ""-v important,general,playback,file,extra"". This is for playback of an ISO with 9 titles, played on an ION frontend, single core, hyperthreading, gigabit network connection to the backend. There are frequent sections of the log that look like this: {{{ 2011-06-23 06:05:05.792052 I [20123/20123] CoreContext ringbuffer.cpp:1140 (ReadPriv) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): ReadPriv(..2048, normal) @4096 -- begin 2011-06-23 06:05:05.796801 I [20123/20323] RingBuffer ringbuffer.cpp:822 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): safe_read(...@7340032, 1048576) -- begin 2011-06-23 06:05:05.822328 I [20123/20323] RingBuffer ringbuffer.cpp:836 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): safe_read(...@7340032, 1048576) -> 1048576, took 26 ms (322.639Mbps) 2011-06-23 06:05:05.822364 I [20123/20323] RingBuffer ringbuffer.cpp:849 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): rbwpos += 1024K requested 1024K in read 2011-06-23 06:05:05.822387 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:05.872488 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:05.922579 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:05.972667 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.022773 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.072870 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.122967 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.173060 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.223177 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.273272 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.323366 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.373455 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.423552 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.473641 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.523730 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.573818 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.623906 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.674175 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.724286 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.774376 I [20123/20323] RingBuffer ringbuffer.cpp:896 (run) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): @ end of read ahead loop 2011-06-23 06:05:06.792228 I [20123/20123] CoreContext ringbuffer.cpp:1224 (ReadPriv) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): ReadPriv(..2048, normal) -- copying data 2011-06-23 06:05:06.792280 I [20123/20123] CoreContext ringbuffer.cpp:1239 (ReadPriv) - RingBuf(myth://Videos@192.168.0.205:6543/test.iso): ReadPriv(..2048, normal) -- checksum 16626 }}} Adding extra instrumentation indicates that the thread running ReadPriv() is delayed for 1 second in the WaitForReadsAllowed() call in the generalWait.wait() statement, while the readahead thread is idle. It appears that readsallowed is changing from false to true without a notification, resulting in the full 1000ms wait. Not sure if the lack of notification is by design. A workaround is to change the 1000ms timeout in WaitForReadsAllowed() to something small like 25ms, resulting in big improvements in startup time. In this example, the original startup time is 4s to the bookmark dialog followed by 65s to playback, but with the 25ms timeout the startup time is 1s to the bookmark dialog followed by 14s to playback." Bug Report - General closed minor 0.25 MythTV - Video Playback Master Head medium fixed 0