Opened 6 years ago

Last modified 4 months ago

#12247 new Bug Report - General

recordings slow to start for 1 minute.

Reported by: blm-ubunet@… Owned by: JYA
Priority: minor Milestone: unknown
Component: MythTV - Video Playback Version: Master Head
Severity: low Keywords:
Cc: Ticket locked: no

Description

For precisely one minute after recordings end, attempts to playback (that same recording) succeed only after 10 sec timeouts. This behaviour has been observed in master for some time (months). Good way to see the full screen "Please wait" message.

Seems like the reported recording file status is incorrect or out dated for 1 min. The file reader trying to read from in-progress recording buffer. The "recordings" screen appears to show the correct status.

Have attempted to find clues in the logs.

Attachments (2)

mbe-log.txt (951.1 KB) - added by blm-ubunet@… 6 years ago.
BE log using -v playback,record --loglevel=debug
fe-log.txt (508.0 KB) - added by blm-ubunet@… 6 years ago.
FE log using -v playback,record --loglevel=debug

Download all attachments as: .zip

Change History (10)

comment:1 Changed 6 years ago by JYA

Status: newinfoneeded_new

Have attempted to find clues in the logs.

That's great so where are they?

I'm sure when creating your bug you saw the massive header on how to create a ticket: https://code.mythtv.org/trac/wiki/TicketHowTo

comment:2 Changed 6 years ago by Raymond Wagner

Any chance this is nothing more than some jobqueue task such as commflagging waiting until a recording is complete, and then running full bore, overloading an underpowered system?

comment:3 Changed 6 years ago by blm-ubunet@…

No job queue stuff except metadata lookup Commflag does not work here (never read reports of it working).

That fact that this is:

  • 100% reproductible/repeatable
  • precisely 1 min post recording end
  • exactly 10sec timeouts
  • recording screen shows correct status at all times.

and the frontend log just FE doing nothing for 10sec might have been strong clues.

Attached logs are for short recording that ends at 8:02 FE log shows successful (fast) playback during recording. FE log shows multiple (5?) slow 10 sec timeouts playback starts.

I can not demonstrate the precise 1 minute window in these logs because of the overhead of starting/stopping playback (can not get 6 attempts inside 60 seconds). But I assure you that is the case.

Changed 6 years ago by blm-ubunet@…

Attachment: mbe-log.txt added

BE log using -v playback,record --loglevel=debug

Changed 6 years ago by blm-ubunet@…

Attachment: fe-log.txt added

FE log using -v playback,record --loglevel=debug

comment:4 Changed 6 years ago by blm-ubunet@…

comment:5 in reply to:  4 Changed 6 years ago by JYA

Replying to blm-ubunet@…:

http://www.gossamer-threads.com/lists/mythtv/dev/572059?#572059 mentions the same behaviour.

I can't draw any comparison there with you reported

comment:6 Changed 6 years ago by blm-ubunet@…

Please read again with open mind. ​http://www.gossamer-threads.com/lists/mythtv/dev/572059?#572059 post #1 <quote>Another issue I see, is when a just finished in-progress recording (in the same minute it closed) is played, the delay is between 10-20 seconds.</quote>

That reads as very similar to this reported bug. The 20sec mentioned could imply/indicate they did not measure against a reference clock & didn't want to imply it was exactly 10sec.

comment:7 Changed 6 years ago by paulh

Status: infoneeded_newnew

comment:8 Changed 4 months ago by Klaas de Waal

This problem can be reproduced with today's master. The only difference is that the wait time before the recording starts is now 15 seconds instead of 10.

Reproducing is trivial:

  • start a recording (either via schedule or by pressing "R" in the guide)
  • the recording is now displayed green in the "Watch Recordings" page
  • stop the recording
  • the recording is now displayed in white in the "Watch Recordings" page
  • give playback command
  • NOW wait for 15 seconds and watch the black screen
  • then playback starts

As described, when the playback command is given one minute or more after the recording has stopped the playback starts immediately.

Relevant bits from the frontend log:

Mar  8 09:08:00 myth3 mythfrontend: mythfrontend[1276]: N CoreContext audioplayer.cpp:162 (ReinitAudio) AudioPlayer: Enabling Audio
Mar  8 09:08:00 myth3 mythfrontend: mythfrontend[1276]: I CoreContext mythplayer.cpp:787 (OpenFile) Player(5): Opening 'myth://zolder/10020_20200308080600.ts'
Mar  8 09:08:15 myth3 mythfrontend: mythfrontend[1276]: I CoreContext decoders/avformatdecoder.cpp:2037 (ScanStreams) AFD: codec MP2 has 2 channels
Mar  8 09:08:15 myth3 mythfrontend: mythfrontend[1276]: I CoreContext decoders/avformatdecoder.cpp:2539 (OpenAVCodec) AFD: Opened codec 0x55962a40b740, id(MP2) type(Audio)

Backend log of the same interval:

2020-03-08 09:08:00.359814 I  MainServer: MainServer::ANN Playback
2020-03-08 09:08:00.359832 I  MainServer: adding: myth3(143be00) as a client (events: 0)
2020-03-08 09:08:00.383147 I  MainServer: adding: myth3(16c7830) as a file transfer
2020-03-08 09:08:02.202491 I  Reschedule requested for MATCH 0 0 0 2020-03-11T23:30:00Z EITScanner
2020-03-08 09:08:03.953994 I  Scheduled 132 items in 1.7 = 0.74 match + 0.87 check + 0.08 place
2020-03-08 09:08:15.483637 I  Monitor sock(7fd3103fdd90) 'zolder' disconnected
2020-03-08 09:08:15.484857 I  Monitor sock(150d8d0) 'zolder' disconnected
Note: See TracTickets for help on using tickets.