Opened 13 years ago

Closed 13 years ago

#9864 closed Bug Report - General (fixed)

RingBuffer locking problem

Reported by: Jim Stichnoth <stichnot@…> 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)

version.txt (767 bytes) - added by Jim Stichnoth <stichnot@…> 13 years ago.
mythfrontend.log.gz (74.6 KB) - added by Jim Stichnoth <stichnot@…> 13 years ago.
9864-master-v1.patch (883 bytes) - added by danielk 13 years ago.
Possible fix.

Download all attachments as: .zip

Change History (8)

Changed 13 years ago by Jim Stichnoth <stichnot@…>

Attachment: version.txt added

Changed 13 years ago by Jim Stichnoth <stichnot@…>

Attachment: mythfrontend.log.gz added

comment:1 Changed 13 years ago by danielk

Owner: changed from Janne Grunau to danielk
Status: newaccepted

I think I can fix this a bit better than just reducing the timeout. Give me a few days. :)

Changed 13 years ago by danielk

Attachment: 9864-master-v1.patch added

Possible fix.

comment:2 Changed 13 years ago by danielk

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 danielk

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 Jim Stichnoth <stichnot@…>

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 Github

Milestone: unknown0.25
Resolution: fixed
Status: acceptedclosed

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

Note: See TracTickets for help on using tickets.