Recording issues with macOS Sierra beta 1

[blackarrow]

Hi,

I have (inadvisably) upgraded to macOS Sierra public beta 1. Apart from kernel panicking whenever I plug in my RAID thunderbolt HDD enclosure (bother), MythTV backend 0.27 now also fails at times to record to the inbuilt hard drive:

2016-07-12 14:22:23.541031 I [1237/11011] Scheduler scheduler.cpp:2690 (HandleRecordingStatusChange) - Tuning recording: "Dinosaur Train":"Buddy Explores the Tyrannosaurs": channel 1022 on cardid 10, sourceid 1
2016-07-12 14:22:25.447881 I [1237/2831] CoreContext scheduler.cpp:705 (UpdateRecStatus) - Updating status for "Dinosaur Train":"Buddy Explores the Tyrannosaurs" on cardid 10 (Tuning => Recording)
2016-07-12 14:22:25.600721 I [1237/9987] TVRecEvent tv_rec.cpp:4130 (TuningNewRecorder) - TVRec[10]: rec->GetPathname(): '/MythTV/1022_20160712042200.mpg'
2016-07-12 14:22:25.601517 E [1237/9987] TVRecEvent recorders/recorderbase.cpp:206 (SetStrOption) - RecBase[10](10.0.1.8-0): SetStrOption(...recordingtype): Option not in profile.
2016-07-12 14:22:25.868599 I [1237/51807] ProcessRequest mainserver.cpp:1446 (HandleAnnounce) - MainServer::ANN Monitor
2016-07-12 14:22:25.868607 I [1237/51807] ProcessRequest mainserver.cpp:1448 (HandleAnnounce) - adding: iMac.local as a client (events: 0)
2016-07-12 14:22:25.869111 I [1237/51807] ProcessRequest mainserver.cpp:1446 (HandleAnnounce) - MainServer::ANN Monitor
2016-07-12 14:22:25.869116 I [1237/51807] ProcessRequest mainserver.cpp:1448 (HandleAnnounce) - adding: iMac.local as a client (events: 1)
2016-07-12 14:22:25.877615 W [1237/47367] SystemEvent mythsystemevent.cpp:55 (run) - MythSystemEventHandler: Command 'stat "/Volumes/Mass Storage/MythTV" &' returned 142
2016-07-12 14:22:25.957764 I [1237/2831] CoreContext scheduler.cpp:705 (UpdateRecStatus) - Updating status for "MasterChef Australia":"California Week" on cardid 12 (Tuning => Recording)
2016-07-12 14:22:26.034055 I [1237/10499] TVRecEvent tv_rec.cpp:4130 (TuningNewRecorder) - TVRec[12]: rec->GetPathname(): '/MythTV/1010_20160712042200.mpg'
2016-07-12 14:22:26.034252 E [1237/10499] TVRecEvent recorders/recorderbase.cpp:206 (SetStrOption) - RecBase[12](10.0.1.9-0): SetStrOption(...recordingtype): Option not in profile.
2016-07-12 14:22:33.830433 I [1237/11011] Scheduler scheduler.cpp:2140 (HandleReschedule) - Reschedule requested for MATCH 0 0 0 - MythFillDatabase
2016-07-12 14:22:34.369808 I [1237/11011] Scheduler scheduler.cpp:2253 (HandleReschedule) - Scheduled 110 items in 0.5 = 0.01 match + 0.47 check + 0.03 place
2016-07-12 15:13:41.284163 W [1237/56583] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/MythTV/1022_20160712042200.mpg:75): write(37788) cnt 4 total 239324 -- took a long time, 4844 ms
2016-07-12 15:13:41.285731 I [1237/9987] TVRecEvent tv_rec.cpp:1050 (HandleStateChange) - TVRec[10]: Changing from RecordingOnly to None
2016-07-12 15:13:41.286686 I [1237/10499] TVRecEvent tv_rec.cpp:1050 (HandleStateChange) - TVRec[12]: Changing from RecordingOnly to None
2016-07-12 15:13:41.302557 I [1237/51807] ProcessRequest mainserver.cpp:1446 (HandleAnnounce) - MainServer::ANN Playback
2016-07-12 15:13:41.302563 I [1237/51807] ProcessRequest mainserver.cpp:1448 (HandleAnnounce) - adding: iMac.local as a client (events: 0)
2016-07-12 15:13:45.788486 I [1237/9987] TVRecEvent tv_rec.cpp:834 (FinishedRecording) - TVRec[10]: FinishedRecording(1022_2016-07-12T04:22:00Z) damaged recq:<RecordingQuality overall_score="0" key="1022_2016-07-12T04:22:00Z" countinuity_error_count="0" packet_count="99136">
<Gap start="2016-07-12T04:22:00Z" end="2016-07-12T04:22:26Z" duration="26" />
</RecordingQuality>

2016-07-12 15:13:45.789705 I [1237/2831] CoreContext scheduler.cpp:705 (UpdateRecStatus) - Updating status for "Dinosaur Train":"Buddy Explores the Tyrannosaurs" on cardid 10 (Recording => Recorded)
2016-07-12 15:13:47.355051 I [1237/11783] SSDP mythdbcon.cpp:409 (PurgeIdleConnections) - New DB connection, total: 11
2016-07-12 15:13:47.933078 W [1237/58635] RecThread threadedfilewriter.cpp:351 (Flush) - TFW(/MythTV/1010_20160712042200.mpg:112): Taking a long time to flush.. buffer size 247032
2016-07-12 15:13:50.073890 W [1237/58635] RecThread threadedfilewriter.cpp:351 (Flush) - TFW(/MythTV/1010_20160712042200.mpg:112): Taking a long time to flush.. buffer size 247032
2016-07-12 15:13:52.222189 W [1237/58635] RecThread threadedfilewriter.cpp:351 (Flush) - TFW(/MythTV/1010_20160712042200.mpg:112): Taking a long time to flush.. buffer size 247032
2016-07-12 15:13:54.368808 W [1237/58635] RecThread threadedfilewriter.cpp:351 (Flush) - TFW(/MythTV/1010_20160712042200.mpg:112): Taking a long time to flush.. buffer size 247032
2016-07-12 15:13:54.524621 W [1237/56839] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/MythTV/1010_20160712042200.mpg:112): write(65424) cnt 4 total 247032 -- took a long time, 18100 ms
2016-07-12 15:13:54.563962 I [1237/11011] Scheduler scheduler.cpp:2140 (HandleReschedule) - Reschedule requested for CHECK -3 1288 0 UpdateRecStatus2 | Dinosaur Train | Buddy Explores the Tyrannosaurs | Buddy, an adopted T. rex, wishes he knew more about his T. rex ancestors. So, Dad takes him and Tiny on the Dinosaur Train back to the early Cretaceous, to visit an ancestor: an earlier version of Tyrannosaurus rex. |
2016-07-12 15:13:54.564947 I [1237/10499] TVRecEvent tv_rec.cpp:834 (FinishedRecording) - TVRec[12]: FinishedRecording(1010_2016-07-12T04:22:00Z) damaged recq:<RecordingQuality overall_score="0" key="1010_2016-07-12T04:22:00Z" countinuity_error_count="0" packet_count="100348">
<Gap start="2016-07-12T04:22:00Z" end="2016-07-12T04:22:26Z" duration="26" />
</RecordingQuality>

About 80% of the recordings are finishing early, presumably due to the "Taking a long time to flush.." issue.

FYI this is the latest iMac I could buy with the higher spec processor and RAM, so I doubt it it hardware related.

Should we chalk this up to Apple's beta software quality, or is there something else I can do to tweak / investigate? Or try out a build of 0.28?

Thanks,
Hamish.

[pvr4me]

I agree that it was inadvisable to install a newly-released public beta on a machine running a 'production' system like Myth!

On the other hand, that is a really curious result. Could you check a couple of things?

1) For reasons that are too complicated to explain here, I've found the disk-speed-test-tool from Black Magic gives a reliable measure of disk throughput. I don't know if it works with Sierra, yet, but hopefully it will show whether or not there is a write speed problem with your recording drive:

https://itunes.apple.com/ca/app/blackma ... 4550?mt=12

2) I wonder if this is somehow related to the problems with your Thunderbolt drive. Please use Console.app and scan for file and drive-related errors. Just spitballing, but maybe your Mac is repeatedly attempting to mount the TBolt drive and pausing for a very long time each time it tries?

Craig
(Do you have a good backup to go back to?)

[blackarrow]

A quick update...

After the first 24 hours or so this issue disappeared. Perhaps there was a process that was highly disk or CPU intensive that caused this? I ran the Black Magic tool, getting write speeds > 150Mb/s. The TBolt drive was not plugged in because doing so would kernel panic the machine.

Also, with public beta 2 the kernel panic on RAID plugin went away, so all is good again.

Still looking forward to beta testing 0.28 when it is ready.

Cheers, Hamish

[pvr4me]

A quick update...

After the first 24 hours or so this issue disappeared. Perhaps there was a process that was highly disk or CPU intensive that caused this? I ran the Black Magic tool, getting write speeds > 150Mb/s. The TBolt drive was not plugged in because doing so would kernel panic the machine.

Also, with public beta 2 the kernel panic on RAID plugin went away, so all is good again.

Still looking forward to beta testing 0.28 when it is ready.

I love it when things fix themselves!

Spotlight could have been contributing to the timing issue?

BTW, it would be cool to be able to say to Siri "Play the latest recorded episode of XXX"! Maybe some day.

Craig