Modify
Warning Please read the Ticket HowTo before creating or commenting on a ticket. Failure to do so may cause your ticket to be rejected or result in a slower response.

Opened 3 years ago

Closed 3 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@…> 3 years ago.
mythfrontend.log.gz (74.6 KB) - added by Jim Stichnoth <stichnot@…> 3 years ago.
9864-master-v1.patch (883 bytes) - added by danielk 3 years ago.
Possible fix.

Download all attachments as: .zip

Change History (8)

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

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

comment:1 Changed 3 years ago by danielk

  • Owner changed from janne to danielk
  • Status changed from new to accepted

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

Changed 3 years ago by danielk

Possible fix.

comment:2 Changed 3 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 3 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 3 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 3 years ago by Github

  • Milestone changed from unknown to 0.25
  • Resolution set to fixed
  • Status changed from accepted to 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

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'new'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.