From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S935080AbcATUZ2 (ORCPT ); Wed, 20 Jan 2016 15:25:28 -0500 Received: from mx2.suse.de ([195.135.220.15]:51061 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754719AbcATUZX (ORCPT ); Wed, 20 Jan 2016 15:25:23 -0500 Subject: Re: linux-4.4 bisected: kwin5 stuck on kde5 loading screen with radeon To: Mario Kleiner , =?UTF-8?B?VmlsbGUgU3lyasOkbMOk?= References: <5698CB20.9050602@suse.cz> <20160115122629.GC23290@intel.com> <5699C5E5.90702@gmail.com> <569CC357.8030302@suse.cz> Cc: Alex Deucher , =?UTF-8?Q?Christian_K=c3=b6nig?= , Daniel Vetter , mgraesslin@kde.org, David Airlie , dri-devel@lists.freedesktop.org, LKML , kwin@kde.org From: Vlastimil Babka X-Enigmail-Draft-Status: N1110 Message-ID: <569FED2D.8000603@suse.cz> Date: Wed, 20 Jan 2016 21:25:17 +0100 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.3.0 MIME-Version: 1.0 In-Reply-To: <569CC357.8030302@suse.cz> Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 8bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 >>> >