Bug 109114 - [CI][BAT] igt@debugfs_test@read_all_entries* - incomplete
Summary: [CI][BAT] igt@debugfs_test@read_all_entries* - incomplete
Status: CLOSED NOTABUG
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: XOrg git
Hardware: Other All
: highest normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2018-12-20 08:52 UTC by Martin Peres
Modified: 2018-12-20 13:33 UTC (History)
4 users (show)

See Also:
i915 platform: HSW
i915 features:

Attachments

Description Martin Peres 2018-12-20 08:52:00 UTC 
This issue has been seen a lot lately in pre-merge: 

https://intel-gfx-ci.01.org/tree/drm-tip/Trybot_3430/fi-hsw-peppy/igt@debugfs_test@read_all_entries.html

https://intel-gfx-ci.01.org/tree/drm-tip/Trybot_3434/fi-hsw-peppy/igt@debugfs_test@read_all_entries.html

<6> [30.904516] Console: switching to colour dummy device 80x25
<6> [30.904628] [IGT] debugfs_test: executing
<6> [30.923288] [IGT] debugfs_test: starting subtest read_all_entries
<7> [30.924049] [IGT] Reading file "i915_rps_boost_info"
<7> [30.925515] [IGT] Reading file "i915_drrs_status"
<7> [30.925819] [IGT] Reading file "i915_sseu_status"
<7> [30.925972] [IGT] Reading file "i915_ddb_info"
<7> [30.926115] [IGT] Reading file "i915_wa_registers"
<7> [30.926251] [IGT] Reading file "i915_dp_mst_info"
<7> [30.926643] [IGT] Reading file "i915_shared_dplls_info"
<7> [30.926865] [IGT] Reading file "i915_shrinker_info"
<7> [30.927003] [IGT] Reading file "i915_rcs_topology"
<7> [30.927141] [IGT] Reading file "i915_engine_info"
<7> [30.928049] [IGT] Reading file "i915_display_info"
<7> [30.928602] [IGT] Reading file "i915_dmc_info"
<7> [30.928766] [IGT] Reading file "i915_power_domain_info"
<7> [30.929654] [IGT] Reading file "i915_runtime_pm_status"
<7> [30.929806] [IGT] Reading file "i915_energy_uJ"
<7> [30.929946] [IGT] Reading file "i915_edp_psr_status"
<7> [30.930082] [IGT] Reading file "i915_llc"
<7> [30.930216] [IGT] Reading file "i915_ppgtt_info"
<7> [30.931156] [IGT] Reading file "i915_swizzle_info"
<7> [30.931314] [IGT] Reading file "i915_forcewake_domains"
<7> [30.931673] [IGT] Reading file "i915_context_status"
<7> [30.931859] [IGT] Reading file "i915_gem_framebuffer"
<7> [30.932032] [IGT] Reading file "i915_vbt"
<7> [30.932263] [IGT] Reading file "i915_opregion"
<7> [30.932967] [IGT] Reading file "i915_sr_status"
<7> [30.933120] [IGT] Reading file "i915_ips_status"
<7> [30.933258] [IGT] Reading file "i915_fbc_status"
<7> [30.933710] [IGT] Reading file "i915_frontbuffer_tracking"
<7> [30.933854] [IGT] Reading file "i915_ring_freq_table"
<7> [30.934070] [IGT] Reading file "i915_emon_status"
<7> [30.934214] [IGT] Reading file "i915_drpc_info"
<7> [30.934674] [drm:sandybridge_pcode_read [i915]] warning: pcode (read from mbox 5) mailbox access failed for i915_drpc_info [i915]: -6
<7> [30.934813] [IGT] Reading file "i915_reset_info"
<7> [30.934977] [IGT] Reading file "i915_hangcheck_info"
<7> [30.935176] [IGT] Reading file "i915_frequency_info"
<7> [30.935804] [IGT] Reading file "i915_huc_load_status"
<7> [30.935984] [IGT] Reading file "i915_guc_stage_pool"
<7> [30.936790] [IGT] Reading file "i915_guc_load_err_log_dump"
<7> [30.936979] [IGT] Reading file "i915_guc_log_dump"
<7> [30.937140] [IGT] Reading file "i915_guc_load_status"
<7> [30.937299] [IGT] Reading file "i915_guc_info"
<7> [30.937652] [IGT] Reading file "i915_gem_batch_pool"
<7> [30.937821] [IGT] Reading file "i915_gem_interrupt"
<7> [30.938089] [IGT] Reading file "i915_gem_fence_regs"
<7> [30.938265] [IGT] Reading file "i915_gem_stolen"
<7> [30.938746] [IGT] Reading file "i915_gem_gtt"
<7> [30.938984] [IGT] Reading file "i915_gem_objects"
<7> [30.939274] [IGT] Reading file "i915_capabilities"
<7> [30.939686] [IGT] Reading file "i915_edp_psr_debug"
<7> [30.939830] [IGT] Reading file "i915_drrs_ctl"
<7> [30.939966] [IGT] Reading file "i915_ipc_status"
<7> [30.940083] [IGT] Reading file "i915_hpd_short_storm_ctl"
<7> [30.940238] [IGT] Reading file "i915_hpd_storm_ctl"
<7> [30.940997] [IGT] Reading file "i915_guc_log_relay"
<7> [30.941174] [IGT] Reading file "i915_guc_log_level"
<7> [30.941312] [IGT] Reading file "i915_dp_test_active"
<7> [30.942071] [IGT] Reading file "i915_dp_test_type"
<7> [30.942220] [IGT] Reading file "i915_dp_test_data"
<7> [30.942593] [IGT] Reading file "i915_fbc_false_color"
<7> [30.942754] [IGT] Reading file "i915_cur_wm_latency"
<7> [30.942934] [IGT] Reading file "i915_spr_wm_latency"
<7> [30.943104] [IGT] Reading file "i915_pri_wm_latency"
<7> [30.943277] [IGT] Reading file "i915_next_seqno"
<7> [30.943583] [IGT] Reading file "i915_fifo_underrun_reset"
<7> [30.943705] [IGT] Reading file "i915_gpu_info"
<7> [30.948056] [IGT] Reading file "i915_error_state"
<7> [30.948246] [IGT] Reading file "i915_gem_drop_caches"
<7> [30.948637] [IGT] Reading file "i915_ring_test_irq"
<7> [30.948773] [IGT] Reading file "i915_ring_missed_irq"
<7> [30.948890] [IGT] Reading file "i915_cache_sharing"
<7> [30.949613] [IGT] Reading file "i915_wedged"
<7> [30.949980] [IGT] Reading file "i915_forcewake_user"
<7> [30.950331] [IGT] Reading file "i915_hdcp_sink_capability"
<7> [30.950690] [IGT] Reading file "edid_override"
<7> [30.950828] [IGT] Reading file "force"
<7> [30.951051] [IGT] Reading file "i915_psr_sink_status"
<7> [30.951195] [IGT] Reading file "i915_panel_timings"
<7> [30.951332] [IGT] Reading file "i915_dpcd"
<7> [30.951840] [drm:edp_panel_vdd_on [i915]] Turning eDP port A VDD on
<7> [30.951944] [drm:edp_panel_vdd_on [i915]] PP_STATUS: 0x80000008 PP_CONTROL: 0x0000000f
<7> [30.956942] [IGT] Reading file "edid_override"
<7> [30.957627] [IGT] Reading file "force"
<7> [30.957973] [IGT] Reading file "data"
<7> [30.958099] [IGT] Reading file "control"
<7> [30.958536] [IGT] Reading file "data"
<7> [30.958659] [IGT] Reading file "control"
<7> [30.958914] [IGT] Reading file "data"
<7> [30.959384] [drm:intel_atomic_check [i915]] [CONNECTOR:67:eDP-1] Limiting display bpp to 18 instead of EDID bpp 18, requested bpp 36, max platform bpp 36
<7> [30.959785] [drm:intel_dp_compute_config [i915]] DP link computation with max lane count 1 max rate 270000 max bpp 18 pixel clock 76420KHz
<7> [30.959856] [drm:intel_dp_compute_config [i915]] Force DSC en = 0
<7> [30.959927] [drm:intel_dp_compute_config [i915]] DP lane count 1 clock 270000 bpp 18
<7> [30.959999] [drm:intel_dp_compute_config [i915]] DP link rate required 171945 available 270000
<7> [30.960073] [drm:intel_atomic_check [i915]] hw max bpp: 18, pipe bpp: 18, dithering: 1
<7> [30.960146] [drm:intel_dump_pipe_config [i915]] [CRTC:41:pipe A][modeset]
<7> [30.960218] [drm:intel_dump_pipe_config [i915]] output_types: EDP (0x100)
<7> [30.960290] [drm:intel_dump_pipe_config [i915]] output format: RGB
<7> [30.960364] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: EDP, pipe bpp: 18, dithering: 1
<7> [30.960799] [drm:intel_dump_pipe_config [i915]] dp m_n: lanes: 1; gmch_m: 2671072, gmch_n: 4194304, link_m: 148392, link_n: 524288, tu: 64
<7> [30.960869] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0
<7> [30.960941] [drm:intel_dump_pipe_config [i915]] requested mode:
<7> [30.960952] [drm:drm_mode_debug_printmodeline] Modeline 0:"1366x768" 60 76420 1366 1502 1532 1592 768 776 788 800 0x48 0xa
<7> [30.961023] [drm:intel_dump_pipe_config [i915]] adjusted mode:
<7> [30.961032] [drm:drm_mode_debug_printmodeline] Modeline 0:"1366x768" 60 76420 1366 1502 1532 1592 768 776 788 800 0x48 0xa
<7> [30.961105] [drm:intel_dump_pipe_config [i915]] crtc timings: 76420 1366 1502 1532 1592 768 776 788 800, type: 0x48 flags: 0xa
<7> [30.961178] [drm:intel_dump_pipe_config [i915]] port clock: 270000, pipe src size: 1366x768, pixel rate 76420
<7> [30.961250] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled
<7> [30.961322] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0
<7> [30.961395] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: wrpll: 0x0 spll: 0x0
<7> [30.961739] [drm:intel_dump_pipe_config [i915]] planes on this crtc
<7> [30.961858] [drm:intel_dump_pipe_config [i915]] [PLANE:30:primary A] FB:81, fb = 1366x768 format = XR24 little-endian (0x34325258)
<7> [30.961931] [drm:intel_dump_pipe_config [i915]] [PLANE:33:sprite A] disabled, scaler_id = -1
<7> [30.962004] [drm:intel_dump_pipe_config [i915]] [PLANE:38:cursor A] disabled, scaler_id = -1
<7> [30.962176] [drm:intel_atomic_check [i915]] [CONNECTOR:67:eDP-1] Limiting display bpp to 18 instead of EDID bpp 18, requested bpp 36, max platform bpp 36
<7> [30.962249] [drm:intel_dp_compute_config [i915]] DP link computation with max lane count 1 max rate 270000 max bpp 18 pixel clock 76420KHz
<7> [30.963174] [drm:intel_dp_compute_config [i915]] Force DSC en = 0
<7> [30.963246] [drm:intel_dp_compute_config [i915]] DP lane count 1 clock 270000 bpp 18
<7> [30.963318] [drm:intel_dp_compute_config [i915]] DP link rate required 171945 available 270000
<7> [30.963392] [drm:intel_atomic_check [i915]] hw max bpp: 18, pipe bpp: 18, dithering: 1
<7> [30.963714] [drm:intel_dump_pipe_config [i915]] [CRTC:41:pipe A][modeset]
<7> [30.963787] [drm:intel_dump_pipe_config [i915]] output_types: EDP (0x100)
<7> [30.963859] [drm:intel_dump_pipe_config [i915]] output format: RGB
<7> [30.963931] [drm:intel_dump_pipe_config [i915]] cpu_transcoder: EDP, pipe bpp: 18, dithering: 1
<7> [30.964004] [drm:intel_dump_pipe_config [i915]] dp m_n: lanes: 1; gmch_m: 2671072, gmch_n: 4194304, link_m: 148392, link_n: 524288, tu: 64
<7> [30.964073] [drm:intel_dump_pipe_config [i915]] audio: 0, infoframes: 0
<7> [30.964145] [drm:intel_dump_pipe_config [i915]] requested mode:
<7> [30.964155] [drm:drm_mode_debug_printmodeline] Modeline 0:"1366x768" 60 76420 1366 1502 1532 1592 768 776 788 800 0x48 0xa
<7> [30.964226] [drm:intel_dump_pipe_config [i915]] adjusted mode:
<7> [30.964235] [drm:drm_mode_debug_printmodeline] Modeline 0:"1366x768" 60 76420 1366 1502 1532 1592 768 776 788 800 0x48 0xa
<7> [30.964309] [drm:intel_dump_pipe_config [i915]] crtc timings: 76420 1366 1502 1532 1592 768 776 788 800, type: 0x48 flags: 0xa
<7> [30.964381] [drm:intel_dump_pipe_config [i915]] port clock: 270000, pipe src size: 1366x768, pixel rate 76420
<7> [30.964778] [drm:intel_dump_pipe_config [i915]] pch pfit: pos: 0x00000000, size: 0x00000000, disabled
<7> [30.964850] [drm:intel_dump_pipe_config [i915]] ips: 0, double wide: 0
<7> [30.964922] [drm:intel_dump_pipe_config [i915]] dpll_hw_state: wrpll: 0x0 spll: 0x0
<7> [30.964994] [drm:intel_dump_pipe_config [i915]] planes on this crtc
<7> [30.965069] [drm:intel_dump_pipe_config [i915]] [PLANE:30:primary A] FB:81, fb = 1366x768 format = XR24 little-endian (0x34325258)
<7> [30.965142] [drm:intel_dump_pipe_config [i915]] [PLANE:33:sprite A] disabled, scaler_id = -1
<7> [30.965214] [drm:intel_dump_pipe_config [i915]] [PLANE:38:cursor A] disabled, scaler_id = -1
<7> [30.965323] [drm:intel_reference_shared_dpll [i915]] using LCPLL 1350 for pipe A
<7> [30.975572] [drm:intel_edp_backlight_off [i915]] 
<7> [31.184541] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 0
<7> [31.184744] [drm:intel_disable_pipe [i915]] disabling pipe A
<7> [31.193085] [drm:edp_panel_off [i915]] Turn eDP port A panel power off
<7> [31.193188] [drm:edp_panel_off [i915]] Wait for panel power off time
<7> [31.193273] [drm:wait_panel_status [i915]] mask b0000000 value 00000000 status a0000003 control 00000000
<7> [31.245560] [drm:wait_panel_status [i915]] Wait complete
<7> [31.245636] [drm:ilk_hpd_irq_handler [i915]] hotplug event received, stat 0x08000000, dig 0x00000012, pins 0x00000010, long 0x00000010
<7> [31.245717] [drm:intel_hpd_irq_handler [i915]] digital hpd port A - long
<7> [31.245791] [drm:intel_disable_shared_dpll [i915]] disable LCPLL 1350 (active 1, on? 1) for crtc 41
<7> [31.245863] [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [31.245933] [drm:intel_disable_shared_dpll [i915]] disabling LCPLL 1350
<7> [31.246005] [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP port A
<7> [31.246075] [drm:intel_atomic_commit_tail [i915]] [ENCODER:66:DDI A]
<7> [31.246164] [drm:intel_atomic_commit_tail [i915]] [ENCODER:74:DDI B]
<7> [31.246239] [drm:verify_single_dpll_state.isra.100 [i915]] WRPLL 1
<7> [31.246318] [drm:verify_single_dpll_state.isra.100 [i915]] WRPLL 2
<7> [31.246396] [drm:verify_single_dpll_state.isra.100 [i915]] SPLL
<7> [31.246500] [drm:verify_single_dpll_state.isra.100 [i915]] LCPLL 810
<7> [31.246572] [drm:verify_single_dpll_state.isra.100 [i915]] LCPLL 1350
<7> [31.246644] [drm:verify_single_dpll_state.isra.100 [i915]] LCPLL 2700
<7> [31.246720] [drm:intel_enable_shared_dpll [i915]] enable LCPLL 1350 (active 1, on? 0) for crtc 41
<7> [31.246791] [drm:intel_enable_shared_dpll [i915]] enabling LCPLL 1350
<7> [31.246869] [drm:edp_panel_on [i915]] Turn eDP port A panel power on
<7> [31.246943] [drm:wait_panel_power_cycle [i915]] Wait for panel power cycle
<7> [31.896678] [drm:wait_panel_status [i915]] mask b800000f value 00000000 status 00000000 control 00000000
<7> [31.896802] [drm:wait_panel_status [i915]] Wait complete
<7> [31.896918] [drm:edp_panel_on [i915]] Wait for panel power on
<7> [31.897040] [drm:wait_panel_status [i915]] mask b000000f value 80000008 status 9000000a control 00000003
<7> [31.972032] [drm:ilk_hpd_irq_handler [i915]] hotplug event received, stat 0x08000000, dig 0x00000012, pins 0x00000010, long 0x00000010
<7> [31.972165] [drm:intel_hpd_irq_handler [i915]] digital hpd port A - long
<7> [31.972290] [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [31.972535] [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP port A
<7> [32.097986] [drm:wait_panel_status [i915]] Wait complete
<7> [32.098274] [drm:edp_panel_vdd_on [i915]] Turning eDP port A VDD on
<7> [32.098477] [drm:edp_panel_vdd_on [i915]] PP_STATUS: 0x80000008 PP_CONTROL: 0x0000000b
<7> [32.099815] [drm:intel_dp_start_link_train [i915]] Using LINK_BW_SET value 0a
<7> [32.100815] [drm:intel_dp_set_signal_levels [i915]] Using signal levels 00000000
<7> [32.100888] [drm:intel_dp_set_signal_levels [i915]] Using vswing level 0
<7> [32.100957] [drm:intel_dp_set_signal_levels [i915]] Using pre-emphasis level 0
<7> [32.101027] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS1
<7> [32.101905] [drm:intel_dp_start_link_train [i915]] clock recovery OK
<7> [32.101976] [drm:intel_dp_program_link_training_pattern [i915]] Using DP training pattern TPS2
<7> [32.103060] [drm:intel_dp_start_link_train [i915]] Channel EQ done. DP Training successful
<7> [32.103136] [drm:intel_dp_start_link_train [i915]] [CONNECTOR:67:eDP-1] Link Training Passed at Link Rate = 270000, Lane count = 1
<7> [32.103663] [drm:intel_enable_pipe [i915]] enabling pipe A
<7> [32.104100] [drm:intel_edp_backlight_on [i915]] 
<7> [32.104172] [drm:intel_panel_enable_backlight [i915]] pipe A
<7> [32.104253] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 937
<7> [32.312705] [drm:intel_enable_ddi [i915]] Panel doesn't support DRRS
<7> [35.160691] [drm:edp_panel_vdd_off_sync [i915]] Turning eDP port A VDD off
<7> [35.160774] [drm:edp_panel_vdd_off_sync [i915]] PP_STATUS: 0x80000008 PP_CONTROL: 0x00000007
Comment 1 Chris Wilson 2018-12-20 08:59:12 UTC 
Patch to spin forever on while (crc.entries), spins forever on while (crc.entries). Quelle surprise?
Comment 2 Stanislav Lisovskiy 2018-12-20 09:09:04 UTC 
(In reply to Chris Wilson from comment #1)
> Patch to spin forever on while (crc.entries), spins forever on while
> (crc.entries). Quelle surprise?

I guess you mean https://patchwork.freedesktop.org/patch/268758/ which is from Mika Kahola:

+	while (crtc->crc.entries) {
+		usleep_range(100, 200);
+	}
+

But my patch doesn't have any while loops, however it also fails with the same test case, see https://patchwork.freedesktop.org/series/54267/.

Or then it might mean, that we both managed somehow to introduce same regression.
Comment 3 Chris Wilson 2018-12-20 09:29:08 UTC 
Yet you have the similar assumption about the state of crc.entries and a corresponding lockup during crc collection. Circumstantial, maybe. More likely that the assumption on crc.entries is incorrect and you should try and capture your knowledge of crc.entries and how the driver may differ in an igt.
Comment 4 Stanislav Lisovskiy 2018-12-20 09:47:35 UTC 
(In reply to Chris Wilson from comment #3)
> Yet you have the similar assumption about the state of crc.entries and a
> corresponding lockup during crc collection. Circumstantial, maybe. More
> likely that the assumption on crc.entries is incorrect and you should try
> and capture your knowledge of crc.entries and how the driver may differ in
> an igt.

What do you mean by "similar lockup"? I guess previously you were talking about while loop in Mika's patch, waiting on crc.entries, with probably infinite loop, however I'm not doing that, there is only one check for crc.entries state, ok this could be also wrong, however in other code parts this is done exactly same way, that is what I used as example:

int drm_crtc_add_crc_entry(struct drm_crtc *crtc, bool has_frame,
   uint32_t frame, uint32_t *crcs)
{
      struct drm_crtc_crc *crc = &crtc->crc;
      struct drm_crtc_crc_entry *entry;

      int head, tail;

      spin_lock(&crc->lock);

      /* Caller may not have noticed yet that userspace has stopped reading */
      if (!crc->entries) {
            spin_unlock(&crc->lock);
            return -EINVAL;
      }

...
Comment 5 Mika Kahola 2018-12-20 11:43:36 UTC 
My patch was just a quick experiment. It was never meant to be a complete solution. I wanted to try out if we need to wait some time if we have crc entries. As I didn't know how much waiting time would have been enough, I tried this idea with a possibly infinite loop. That's why I tried out this idea on trybot and never sent the patch in mailing list for review. It turned out in Trybot run that the idea didn't really work.
Comment 6 Martin Peres 2018-12-20 11:47:38 UTC 
I checked out in intel-gfx and found no patches hit by this issue. So it indeed is likely a regression found in your patches.

Sorry for the noise. Closing!
Comment 7 Stanislav Lisovskiy 2018-12-20 13:33:00 UTC 
I just run these debugfs_tests, with my patch on top of drm-tip on my local ICL U - it doesn't fail even after few runs.. Which is weird :)

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.