Re: [Intel-gfx] [WARNING] v5.12-rc1 in intel_pipe_disable tracepoint

[Ville Syrjälä]

On Mon, Mar 01, 2021 at 07:20:59PM +0200, Ville Syrjälä wrote:
> On Mon, Mar 01, 2021 at 11:59:46AM -0500, Steven Rostedt wrote:
> > 
> > On my test box with latest v5.12-rc1, running with all trace events
> > enabled, I consistently trigger this warning.
> > 
> > It appears to get triggered by the trace_intel_pipe_disable() code.
> > 
> > -- Steve
> > 
> >  ------------[ cut here ]------------
> >  i915 0000:00:02.0: drm_WARN_ON_ONCE(drm_drv_uses_atomic_modeset(dev))
> >  WARNING: CPU: 7 PID: 1258 at drivers/gpu/drm/drm_vblank.c:728 drm_crtc_vblank_helper_get_vblank_timestamp_internal+0x319/0x330 [drm]
> >  Modules linked in: ebtable_filter ebtables bridge stp llc vsock vmw_vmci ipt_REJECT nf_reject_ipv4 iptable_filter ip6t_REJECT nf_reject_ipv6 xt_state xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip6table_filter ip6_tables snd_hda_codec_hdmi snd_h
> > ek snd_hda_codec_generic ledtrig_audio snd_hda_intel snd_intel_dspcfg snd_hda_codec joydev snd_hwdep intel_rapl_msr snd_hda_core hp_wmi i915 iTCO_wdt snd_seq intel_rapl_common iTCO_vendor_support wmi_bmof sparse_keymap snd_seq_device rfkill snd_pcm x86_pkg_t
> > d_timer i2c_algo_bit drm_kms_helper mei_me intel_powerclamp snd mei soundcore i2c_i801 drm coretemp lpc_ich e1000e kvm_intel i2c_smbus kvm irqbypass crct10dif_pclmul crc32_pclmul crc32c_intel serio_raw ghash_clmulni_intel video tpm_infineon wmi ip_tables
> >  CPU: 7 PID: 1258 Comm: Xorg Tainted: G        W         5.12.0-rc1-test+ #12
> >  Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
> >  RIP: 0010:drm_crtc_vblank_helper_get_vblank_timestamp_internal+0x319/0x330 [drm]
> >  Code: 4c 8b 6f 50 4d 85 ed 75 03 4c 8b 2f e8 60 92 45 c2 48 c7 c1 28 a5 3c c0 4c 89 ea 48 c7 c7 15 5a 3c c0 48 89 c6 e8 1f e7 7b c2 <0f> 0b e9 e2 fe ff ff e8 fb 6c 81 c2 66 66 2e 0f 1f 84 00 00 00 00
> >  RSP: 0018:ffffb77580ea7920 EFLAGS: 00010082
> >  RAX: 0000000000000000 RBX: ffff8afe500c0000 RCX: 0000000000000000
> >  RDX: 0000000000000004 RSI: ffffffff833c86b8 RDI: 0000000000000001
> >  RBP: ffffb77580ea7990 R08: 000000700c782173 R09: 0000000000000000
> >  R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000000
> >  R13: ffff8afe41c7eff0 R14: ffffffffc05e0410 R15: ffff8afe456a2bf8
> >  FS:  00007f8f91869f00(0000) GS:ffff8afe5aa00000(0000) knlGS:0000000000000000
> >  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >  CR2: 00007f9523a6cad0 CR3: 0000000001b78002 CR4: 00000000001706e0
> >  Call Trace:
> >   drm_get_last_vbltimestamp+0xaa/0xc0 [drm]
> >   drm_update_vblank_count+0x90/0x2d0 [drm]
> >   drm_crtc_accurate_vblank_count+0x3e/0xc0 [drm]
> >   intel_crtc_get_vblank_counter+0x43/0x50 [i915]
> >   trace_event_raw_event_intel_pipe_disable+0x87/0x110 [i915]
> >   intel_disable_pipe+0x1a8/0x210 [i915]
> 
> Hmm. Yeah we do vblank_off() before pipe_disable() which wants
> to still grab the frame counter in the tracepoint. I think we
> could reorder those two without causing any problems. Either
> that or we put the tracepoint before vblank_off().
> 
> >   ilk_crtc_disable+0x85/0x390 [i915]
> 
> But this part is confusing me. intel_crtc_get_vblank_counter() is
> only supposed to do drm_crtc_accurate_vblank_count() fallback when
> the hardware lacks a working frame counter, and that should only
> be the case for ancient gen2 or semi-ancient i965gm TV output,
> ilk_crtc_disable() is not the function we should be calling in
> either of those cases.

OK, figured this out. It can happen on any platform due to
never initializing .max_vblank_count for pipes that were
disabled at boot. Also spotted some other issues in this
code that needs fixing. I'll mail out some patches...

-- 
Ville Syrjälä
Intel