Opened 13 years ago
Closed 13 years ago
#9864 closed Bug Report - General (fixed)
RingBuffer locking problem
Reported by: | Owned by: | danielk | |
---|---|---|---|
Priority: | minor | Milestone: | 0.25 |
Component: | MythTV - Video Playback | Version: | Master Head |
Severity: | medium | Keywords: | |
Cc: | Ticket locked: | no |
Description
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.
Attachments (3)
Change History (8)
Changed 13 years ago by
Attachment: | version.txt added |
---|
Changed 13 years ago by
Attachment: | mythfrontend.log.gz added |
---|
comment:1 Changed 13 years ago by
Owner: | changed from Janne Grunau to danielk |
---|---|
Status: | new → accepted |
comment:2 Changed 13 years ago by
Jim, changing the timeout of WaitForReadsAllowed?() had no effect in my testing. But if that has an positive effect for you the above patch should have an even greater effect. Please give it a try.
comment:3 Changed 13 years ago by
Jim, please also try master without the patch.. this may have already been fixed as a side effect of changing some thresholds.
comment:4 Changed 13 years ago by
Daniel,
Master without any patch behaves as badly as before.
Your patch gives slightly better performance than just reducing the timeout (both of which give far better performance than no patch).
Combining a reduced timeout with your patch is pretty much equivalent to just using your patch.
comment:5 Changed 13 years ago by
Milestone: | unknown → 0.25 |
---|---|
Resolution: | → fixed |
Status: | accepted → closed |
Fixes #9864. Make sure we wake up any sleepers the when we change from the !readsallowed to the readsallowed state.
This usually happens implicitly simply due to the differences in the size of various buffers and read sizes. But that is a bit fragile and complicates tuning buffer sizes for better overall performance.
If you are experiencing the same timeout problem Jim Stichnoth has been experiencing, this should noticably improve your myth:// streaming performance.
Branch: master Changeset: 5db2d5674b911f607e58fe1bc13bbf308aa33688
I think I can fix this a bit better than just reducing the timeout. Give me a few days. :)