Re: linux-4.4 bisected: kwin5 stuck on kde5 loading screen with radeon

[Vlastimil Babka <vbabka@suse.cz>]

On 01/18/2016 11:49 AM, Vlastimil Babka wrote:
> On 01/16/2016 05:24 AM, Mario Kleiner wrote:
>>
>>
>> On 01/15/2016 01:26 PM, Ville Syrjälä wrote:
>>> On Fri, Jan 15, 2016 at 11:34:08AM +0100, Vlastimil Babka wrote:
>>
>> I'm currently running...
>>
>> while xinit /usr/bin/ksplashqml --test -- :1 ; do echo yay; done
>>
>> ... in an endless loop on Linux 4.4 SMP PREEMPT on HD-5770  and so far i
>> can't trigger a hang after hundreds of runs.
>>
>> Does this also hang for you?
> 
> No, test mode seems to be fine.
> 
>> I think a drm.debug=0x21 setting and grep'ping the syslog for "vblank"
>> should probably give useful info around the time of the hang.
> 
> Attached. Captured by having kdm running, switching to console, running 
> "dmesg -C ; dmesg -w > /tmp/dmesg", switch to kdm, enter password, see 
> frozen splashscreen, switch back, terminate dmesg. So somewhere around 
> the middle there should be where ksplashscreen starts...

Hmm this looks suspicious? (!!! mine)

[  538.918990] [drm:drm_update_vblank_count] updating vblank count on crtc 1: current=385876589, diff=1, hw=622 hw_last=621
[  538.918991] [drm:evergreen_irq_process] IH: D2 vblank
[  538.935035] [drm:radeon_get_vblank_counter_kms] crtc 0: dist from vblank start 3
[  538.935040] [drm:radeon_get_vblank_counter_kms] crtc 0: dist from vblank start 3
[  538.935041] [drm:drm_update_vblank_count] updating vblank count on crtc 0: current=16808100, diff=1, hw=30885 hw_last=30884
[  538.935042] [drm:evergreen_irq_process] IH: D1 vblank
[  538.939702] [drm:drm_wait_vblank] waiting on vblank count 385876590, crtc 1
[  538.939704] [drm:drm_wait_vblank] returning 385876590 to client
[  538.939709] [drm:drm_wait_vblank] waiting on vblank count 385876590, crtc 1
[  538.939710] [drm:drm_wait_vblank] returning 385876590 to client
!!!538.939715] [drm:drm_queue_vblank_event] event on vblank count 385876591, current 385876590, crtc 1
[  538.944452] [drm:drm_wait_vblank] waiting on vblank count 16808101, crtc 0
[  538.944453] [drm:drm_wait_vblank] returning 16808101 to client
[  538.944458] [drm:drm_wait_vblank] waiting on vblank count 16808101, crtc 0
[  538.944460] [drm:drm_wait_vblank] returning 16808101 to client
[  538.944465] [drm:drm_queue_vblank_event] event on vblank count 16808102, current 16808101, crtc 0
[  538.948210] [drm:drm_wait_vblank] waiting on vblank count 16808101, crtc 0
[  538.948212] [drm:drm_wait_vblank] returning 16808101 to client
[  538.948222] [drm:drm_wait_vblank] waiting on vblank count 16808101, crtc 0
[  538.948224] [drm:drm_wait_vblank] returning 16808101 to client
[  538.949589] [drm:drm_wait_vblank] waiting on vblank count 16808101, crtc 0
[  538.949591] [drm:drm_wait_vblank] returning 16808101 to client
[  538.951238] [drm:radeon_get_vblank_counter_kms] crtc 1: dist from vblank start 6
[  538.951245] [drm:radeon_get_vblank_counter_kms] crtc 1: dist from vblank start 7
!!!538.951246] [drm:drm_update_vblank_count] updating vblank count on crtc 1: current=385876590, diff=16776597, hw=3 hw_last=622
[  538.951247] [drm:evergreen_irq_process] IH: D2 vblank
[  538.951746] [drm:radeon_get_vblank_counter_kms] crtc 0: dist from vblank start 4
[  538.951752] [drm:radeon_get_vblank_counter_kms] crtc 0: dist from vblank start 4
[  538.951753] [drm:drm_update_vblank_count] updating vblank count on crtc 0: current=16808101, diff=1, hw=30886 hw_last=30885
[  538.951754] [drm:drm_handle_vblank_events] vblank event on 16808102, current 16808102
[  538.951756] [drm:evergreen_irq_process] IH: D1 vblank
[  538.964570] [drm:radeon_get_vblank_counter_kms] crtc 1: dist from vblank start 7
[  538.964581] [drm:radeon_get_vblank_counter_kms] crtc 1: dist from vblank start -1058
[  538.964583] [drm:drm_update_vblank_count] updating vblank count on crtc 1: current=402653187, diff=1, hw=4 hw_last=3

Could it be that the underflow caused some signed logic to misbehave and fail to detect that we passed 385876591?

Later we have another such big skip (but this time nothing waits for it I guess):

[  541.337813] [drm:drm_update_vblank_count] updating vblank count on crtc 1: current=402653363, diff=16777040, hw=3 hw_last=179



>> Maybe also check XOrg.0.log for (WW) warnings related to flip.
> 
> No such warnings there.
> 
>> thanks,
>> -mario
>>
>>
>>>> Thanks,
>>>> Vlastimil
>>>
>