*** Bug 107883 has been marked as a duplicate of this bug. ***

 Failed assertion: result >= max(0, val - tolerance) && result <= min(context->max, val + tolerance)
(pm_backlight:1230) CRITICAL: actual_brightness [0] did not match expected brightness [937 +- 46]

Per the logs, the IGT test checks results before our driver has properly resumed:

<6>[  374.604627] PM: suspend exit
<7>[  374.605630] [drm:intel_backlight_device_update_status [i915]] updating intel_backlight, brightness=120000/120000
<7>[  374.606169] [drm:intel_backlight_device_get_brightness [i915]] get backlight PWM = 0
<3>[  374.651655] atkbd serio0: Failed to enable keyboard on isa0060/serio0
<7>[  374.660218] [drm:intel_backlight_device_update_status [i915]] updating intel_backlight, brightness=120000/120000
<7>[  374.662657] [IGT] pm_backlight: exiting, ret=99

IGT declares failure above...

<7>[  374.683980] [drm:intel_power_well_enable [i915]] enabling power well 2
<7>[  374.696690] [drm:intel_power_well_disable [i915]] disabling power well 2
<7>[  374.697999] [drm:intel_atomic_check [i915]] [CONNECTOR:71:eDP-1] checking for sink bpp constrains
<7>[  374.698083] [drm:intel_atomic_check [i915]] clamping display bpp (was 36) to EDID reported max of 24
<7>[  374.698144] [drm:intel_dp_compute_config [i915]] DP link computation with max lane count 4 max rate 540000 max bpp 24 pixel clock 533250KHz
<7>[  374.698200] [drm:intel_dp_compute_config [i915]] DP lane count 4 clock 540000 bpp 24
<7>[  374.698256] [drm:intel_dp_compute_config [i915]] DP link rate required 1599750 available 2160000
<7>[  374.698311] [drm:intel_psr_compute_config [i915]] PSR2 not enabled, resolution 3840x2160 > max supported 3640x2304
<7>[  374.698365] [drm:intel_atomic_check [i915]] hw max bpp: 36, pipe bpp: 24, dithering: 0
<7>[  374.698419] [drm:intel_dump_pipe_config [i915]] [CRTC:41:pipe A][modeset]
<7>[  374.698472] [drm:intel_dump_pipe_config [i915]] output_types: EDP (0x100)
<7>[  374.698585] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: EDP, pipe bpp: 24, dithering: 0
<7>[  374.698661] [drm:intel_dump_pipe_config [i915]] dp m_n: lanes: 4; gmch_m: 6212812, gmch_n: 8388608, link_m: 1035468, link_n: 1048576, tu: 64
<7>[  374.698733] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0
<7>[  374.698802] [drm:intel_dump_pipe_config [i915]] requested mode:
<7>[  374.698817] [drm:drm_mode_debug_printmodeline] Modeline 0:"3840x2160" 60 533250 3840 3888 3920 4000 2160 2163 2168 2222 0x48 0xa
<7>[  374.698882] [drm:intel_dump_pipe_config [i915]] adjusted mode:
<7>[  374.698893] [drm:drm_mode_debug_printmodeline] Modeline 0:"3840x2160" 60 533250 3840 3888 3920 4000 2160 2163 2168 2222 0x48 0xa
<7>[  374.698960] [drm:intel_dump_pipe_config [i915]] crtc timings: 533250 3840 3888 3920 4000 2160 2163 2168 2222, type: 0x48 flags: 0xa
<7>[  374.699028] [drm:intel_dump_pipe_config [i915]] port clock: 540000, pipe src size: 3840x2160, pixel rate 533250
<7>[  374.699094] [drm:intel_dump_pipe_config [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1
<7>[  374.699160] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled
<7>[  374.699226] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0
<7>[  374.699294] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: ctrl1: 0x1, cfgcr1: 0x0, cfgcr2: 0x0
<7>[  374.699359] [drm:intel_dump_pipe_config [i915]] planes on this crtc
<7>[  374.699424] [drm:intel_dump_pipe_config [i915]] [PLANE:28:plane 1A] disabled, scaler_id = -1
<7>[  374.699495] [drm:intel_dump_pipe_config [i915]] [PLANE:33:plane 2A] disabled, scaler_id = -1
<7>[  374.699585] [drm:intel_dump_pipe_config [i915]] [PLANE:38:cursor A] disabled, scaler_id = -1
<7>[  374.699670] [drm:intel_atomic_check [i915]] New cdclk calculated to be logical 540000 kHz, actual 540000 kHz
<7>[  374.699741] [drm:intel_atomic_check [i915]] New voltage level calculated to be logical 2, actual 2
<7>[  374.699818] [drm:intel_find_shared_dpll [i915]] [CRTC:41:pipe A] allocated DPLL 0
<7>[  374.699886] [drm:intel_reference_shared_dpll [i915]] using DPLL 0 for pipe A
<7>[  374.700314] [drm:intel_dump_cdclk_state [i915]] Changing CDCLK to 540000 kHz, VCO 8100000 kHz, ref 24000 kHz, bypass 24000 kHz, voltage level 2
<7>[  374.701194] [drm:intel_atomic_commit_tail [i915]] [ENCODER:70:DDI A]
<7>[  374.701253] [drm:intel_atomic_commit_tail [i915]] [ENCODER:77:DDI B]
<7>[  374.701308] [drm:intel_atomic_commit_tail [i915]] [ENCODER:79:DP-MST A]
<7>[  374.701363] [drm:intel_atomic_commit_tail [i915]] [ENCODER:80:DP-MST B]
<7>[  374.701415] [drm:intel_atomic_commit_tail [i915]] [ENCODER:81:DP-MST C]
<7>[  374.701468] [drm:intel_atomic_commit_tail [i915]] [ENCODER:84:DDI C]
<7>[  374.701574] [drm:intel_atomic_commit_tail [i915]] [ENCODER:86:DP-MST A]
<7>[  374.701647] [drm:intel_atomic_commit_tail [i915]] [ENCODER:87:DP-MST B]
<7>[  374.701723] [drm:intel_atomic_commit_tail [i915]] [ENCODER:88:DP-MST C]
<7>[  374.701789] [drm:verify_single_dpll_state.isra.88 [i915]] DPLL 0
<7>[  374.701861] [drm:verify_single_dpll_state.isra.88 [i915]] DPLL 1
<7>[  374.701932] [drm:verify_single_dpll_state.isra.88 [i915]] DPLL 2
<7>[  374.702001] [drm:verify_single_dpll_state.isra.88 [i915]] DPLL 3
<7>[  374.702099] [drm:intel_enable_shared_dpll [i915]] enable DPLL 0 (active 1, on? 0) for crtc 41
<7>[  374.702190] [drm:intel_enable_shared_dpll [i915]] enabling DPLL 0
<7>[  374.702376] [drm:edp_panel_on [i915]] Turn eDP port A panel power on
<7>[  374.702611] [drm:wait_panel_power_cycle [i915]] Wait for panel power cycle
<7>[  374.702847] [drm:wait_panel_status [i915]] mask b800000f value 00000000 status 00000000 control 00000068
<7>[  374.702931] [drm:wait_panel_status [i915]] Wait complete
<7>[  374.703051] [drm:edp_panel_on [i915]] Wait for panel power on
<7>[  374.703182] [drm:wait_panel_status [i915]] mask b000000f value 80000008 status 9000000a control 0000006b
<7>[  374.864872] [drm:wait_panel_status [i915]] Wait complete
<7>[  374.865093] [drm:intel_power_well_enable [i915]] enabling DDI A/E IO power well
<7>[  374.867808] [drm:intel_dp_start_link_train [i915]] Using LINK_RATE_SET value 06
<7>[  374.868759] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 00000000
<7>[  374.868900] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 0
<7>[  374.869033] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 0
<7>[  374.869169] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS1
<7>[  374.870336] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 04000000
<7>[  374.870440] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 1
<7>[  374.870551] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 0
<7>[  374.871709] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 04000000
<7>[  374.871814] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 1
<7>[  374.871914] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 0
<7>[  374.873000] [drm:intel_dp_start_link_train [i915]] clock recovery OK
<7>[  374.873106] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS3
<7>[  374.874472] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 05000000
<7>[  374.874618] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 1
<7>[  374.874724] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 1
<7>[  374.876176] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 05000000
<7>[  374.876279] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 1
<7>[  374.876381] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 1
<7>[  374.877750] [drm:intel_dp_start_link_train [i915]] Channel EQ done. DP Training successful
<7>[  374.877862] [drm:intel_dp_start_link_train [i915]] [CONNECTOR:71:eDP-1] Link Training Passed at Link Rate = 540000, Lane count = 4
<7>[  374.879864] [drm:intel_enable_pipe [i915]] enabling pipe A
<7>[  374.880012] [drm:intel_edp_backlight_on [i915]] 
<7>[  374.880116] [drm:intel_panel_enable_backlight [i915]] pipe A
<7>[  374.880315] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 120000

...but it is only here that we enable backlight after resume.

Should we do this?

diff --git a/tests/pm_backlight.c b/tests/pm_backlight.c
index 32808cdf6ca4..8d6a92c98004 100644
--- a/tests/pm_backlight.c
+++ b/tests/pm_backlight.c
@@ -184,6 +184,8 @@ test_fade_with_suspend(struct context *context, igt_output_t *output)
 
 	igt_system_suspend_autoresume(SUSPEND_STATE_MEM, SUSPEND_TEST_NONE);
 
+	igt_assert(igt_wait_for_pm_status(IGT_RUNTIME_PM_STATUS_ACTIVE));
+
 	test_fade(context);
 }

Suspect commit 377752242995 ("tests/pm_backlight.c : Brightness test with DPMS and System suspend.")

A CI Bug Log filter associated to this bug has been updated:

{- ALL: igt@pm_backlight@fade_with_suspend - fail - Failed assertion: result >= max(0, val - tolerance) && result <= min(context->max, val + tolerance) -}
{+ ALL: igt@pm_backlight@fade_with_suspend - fail/dmesg-fail - Failed assertion: result >= max(0, val - tolerance) && result <= min(context->max, val + tolerance) +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_213/fi-hsw-peppy/igt@pm_backlight@fade_with_suspend.html
* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_214/fi-hsw-peppy/igt@pm_backlight@fade_with_suspend.html
* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_215/fi-hsw-peppy/igt@pm_backlight@fade_with_suspend.html

Last seen on CI_DRM_5875_full (2 weeks, 3 days old), after failing 100% of the time.

Looks like a fix landed. Thanks!

(In reply to Martin Peres from comment #7)
> Last seen on CI_DRM_5875_full (2 weeks, 3 days old), after failing 100% of
> the time.
> 
> Looks like a fix landed. Thanks!

No failures since this then. Closing and archiving.

The CI Bug Log issue associated to this bug has been archived.

New failures matching the above filters will not be associated to this bug anymore.