recordings slow to start for 1 minute.

[blm-ubunet@…]

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.

[JYA]

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

[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?

[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.

[blm-ubunet@…]

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

[blm-ubunet@…]

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

[blm-ubunet@…]

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

[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

[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.

[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

[Stuart Auchterlonie]

Closing all old tickets in trac.

If your issue still persists, please open an issue in Github ​https://github.com/MythTV/mythtv/issues

and reference the existing trac ticket.