#6 DCP race conditions around hotplug/modeset
Opened by marcan. Modified

Two related issues:

  • Swallowed swaps not being handled properly
  • Power sequencing issues

Ref: https://www.reddit.com/r/AsahiLinux/comments/1bgr4rc/still_issues_with_m2_mac_mini_wake_from_sleep/kvmh9b9/

Relevant log (M2 Mac Mini):

Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DP2HDMI HPD irq, connected:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:146: IOMFB: IOAVVideoInterface terminated
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: oInterfaceIOAV.cpp:1094: void VideoInterfaceIOAV::unplug_gated(IOAVVideoInterface *): display HPD removed
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:146: IOMFB: IOAVVideoInterface terminated
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: PPipeDCP_H13P.cpp:10490: set_run_mode_safe: deferring: 4 -> 1
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: PPipeDCP_H13P.cpp:10395: virtual IOMFBStatus IOMFB::UPPipeDCP_H13P::ready_for_run_mode_change(IOMFB::AppleRegisterStream *): initiating deferred run mod
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: UPTSQManager.cpp:150: IOMFBStatus IOMFB::UPTSQManager::power_down_M3(IOMFB::AppleRegisterStream *, UPTSQManager::ModeChangeWaiter *): request mode ch
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: oInterfaceIOAV.cpp:1094: void VideoInterfaceIOAV::unplug_gated(IOAVVideoInterface *): display HPD removed
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: UPTSQManager.cpp:162: IOMFBStatus IOMFB::UPTSQManager::power_down_M3(IOMFB::AppleRegisterStream *, UPTSQManager::ModeChangeWaiter *): disabling M3
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: PPipeDCP_H13P.cpp:10468: set_run_mode_safe: no need to defer: 1 -> 0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:1356: set_device_enabled_gated: current state: 1, requested state: 0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 21
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:0, valid_mode:1
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:0, valid_mode:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 20
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_hotplug() connected:0 valid_mode:0 nr_modes:20
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 20
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DP2HDMI HPD irq, connected:1
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_dptx_connect(port=0)
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1962: IOMFB: swap_submit_dcp: swallowed swap ID 2376 as fControllerPowerState is 0 for External Display
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1967: IOMFB: swap_submit_dcp: swallowed swap ID 2376 as timinsg are not enabled for External Display
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_poweroff() done
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 21
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 15
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: set_drive_settings: 4:0:44:0:0:0:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: set_drive_settings: 4:0:44:0:0:0:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:135: IOMFB: IOAVVideoInterface published
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:714: IOMFBStatus VideoInterfaceIOAV::plug_gated(IOAVVideoInterface *, bool): display HPD asserted
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:135: IOMFB: IOAVVideoInterface published
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:714: IOMFBStatus VideoInterfaceIOAV::plug_gated(IOAVVideoInterface *, bool): display HPD asserted
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:1, valid_mode:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:1, valid_mode:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_hotplug() connected:1 valid_mode:0 nr_modes:35
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_poweron: DP2HDMI HPD connected:1
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_dptx_connect(port=0)
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_poweron() starting
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:5931: IOMFBParameter_adaptive_sync Req minRR = 0x0, mediaTargetRate = 0x0, Fractional Rate = 0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: set_digital_out_mode(color:0 timing:43) "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: set_digital_out_mode() color mode depth:0 format:0 colorimetry:0 eotf:0 range:0
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7462: set_digital_out_mode: Modeset requested for colorID: 0, timingID: 43
Mar 20 07:32:19 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: PPipeDCP_H13P.cpp:18011: Dual pipe disabled offset 0
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7700: set_mode: timingID: 43 colorID: 0
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: oInterfaceIOAV.cpp:1268: auto VideoInterfaceIOAV::set_mode(uint32_t, uint32_t, uint32_t *, uint32_t *, IOAVArray *, IOAVArray *)::(anonymous class)::ope
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7739: setmode failed
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7758: ERROR: Modeset done, but pipe not enabled: fSoftPowerState=1, fDisplayPowerState=0, fHardPowerState=1
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7465: set_digital_out_mode returned 80000104
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: set_digital_out_mode finished:8296
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1962: IOMFB: swap_submit_dcp: swallowed swap ID 2377 as fControllerPowerState is 0 for External Display
Mar 20 07:32:20 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1967: IOMFB: swap_submit_dcp: swallowed swap ID 2377 as timinsg are not enabled for External Display
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DP2HDMI HPD irq, connected:0
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:146: IOMFB: IOAVVideoInterface terminated
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: oInterfaceIOAV.cpp:1094: void VideoInterfaceIOAV::unplug_gated(IOAVVideoInterface *): display HPD removed
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:146: IOMFB: IOAVVideoInterface terminated
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: oInterfaceIOAV.cpp:1094: void VideoInterfaceIOAV::unplug_gated(IOAVVideoInterface *): display HPD removed
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:0, valid_mode:1
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:0, valid_mode:0
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 21
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_hotplug() connected:0 valid_mode:0 nr_modes:35
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 20
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1962: IOMFB: swap_submit_dcp: swallowed swap ID 2378 as fControllerPowerState is 0 for External Display
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:1967: IOMFB: swap_submit_dcp: swallowed swap ID 2378 as timinsg are not enabled for External Display
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_poweroff() done
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_dptx_disconnect(port=0)
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 21
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DP2HDMI HPD irq, connected:1
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_dptx_connect(port=0)
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: AppleDCPDPTX.cpp:355: [AFK]powering nub 0x871140
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: DCPDP13Service.cpp:60: [AFK]version: 14
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: DCPDPService.cpp:76: [AFK]version: 14
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: AppleDCPMCDP29XX.cpp:94: [AFK]matched 30000
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 21
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 15
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: set_drive_settings: 4:0:70:0:0:0:0
Mar 20 07:32:27 mac-mini kernel: apple-dcp 271c00000.dcp: set_drive_settings: 4:0:72:0:0:0:0
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:135: IOMFB: IOAVVideoInterface published
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:714: IOMFBStatus VideoInterfaceIOAV::plug_gated(IOAVVideoInterface *, bool): display HPD asserted
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:135: IOMFB: IOAVVideoInterface published
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: eoInterfaceIOAV.cpp:714: IOMFBStatus VideoInterfaceIOAV::plug_gated(IOAVVideoInterface *, bool): display HPD asserted
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: TimingElements without valid modes!
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:1, valid_mode:0
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: dcp_hotplug() connected:1 valid_mode:0 nr_modes:0
Mar 20 07:32:28 mac-mini kernel: apple-dcp 271c00000.dcp: cb_hotplug() connected:1, valid_mode:0

Note color mode seems to be wrong. Previous modeset (boot time) was:

Mar 20 07:28:14 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: FramebufferDCP.cpp:5931: IOMFBParameter_adaptive_sync Req minRR = 0x0, mediaTargetRate = 0x0, Fractional Rate = 0
Mar 20 07:28:14 mac-mini kernel: apple-dcp 271c00000.dcp: set_digital_out_mode(color:69 timing:46) "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x0
Mar 20 07:28:14 mac-mini kernel: apple-dcp 271c00000.dcp: set_digital_out_mode() color mode depth:8 format:0 colorimetry:16 eotf:0 range:0
Mar 20 07:28:14 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7462: set_digital_out_mode: Modeset requested for colorID: 69, timingID: 46
Mar 20 07:28:14 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: PPipeDCP_H13P.cpp:18011: Dual pipe disabled offset 0
Mar 20 07:28:15 mac-mini kernel: apple-dcp 271c00000.dcp: RTKit: syslog message: nifiedPipeline.cpp:7700: set_mode: timingID: 46 colorID: 69
Mar 20 07:28:15 mac-mini kernel: apple-dcp 271c00000.dcp: DPTXPort: acking unhandled call 14
[...]

brown paper bag bug: the dptx-phy node in t8112.dtsi and t602x-dieX.dtsi use power-domain in stead of power-domains. Why was it working at all? On initial probe we were probably saved by simple-framebuffer using the dptx-phy power-domain but after that. I think/hope this explains most or all of the weird issue we see with HDMI on M2* desktop systems.

Fixed in https://github.com/jannau/linux/commits/asahi-wip/

possibly fixed by kernel-16k-6.6.3-414.asahi

500ms msleep() in the threaded HPD irq handler which might ack as debounce or is just a significant delay seems to improve stability with a troublesome display display here. See 5ef7d920caa52

Metadata