From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754882AbeDWMd6 (ORCPT ); Mon, 23 Apr 2018 08:33:58 -0400 Received: from mx2.suse.de ([195.135.220.15]:54348 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754729AbeDWMd4 (ORCPT ); Mon, 23 Apr 2018 08:33:56 -0400 Date: Mon, 23 Apr 2018 14:33:55 +0200 Message-ID: From: Takashi Iwai To: Paul Menzel Cc: Jaroslav Kysela , alsa-devel@alsa-project.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH] ALSA: hda: Request driver probe from an async task In-Reply-To: <92d47260-8d68-15f9-02b5-9846f9957106@molgen.mpg.de> References: <92d47260-8d68-15f9-02b5-9846f9957106@molgen.mpg.de> User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka) FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO) MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka") Content-Type: text/plain; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 23 Apr 2018 14:30:36 +0200, Paul Menzel wrote: > > Dear Takashi, > > > On 04/23/18 14:21, Takashi Iwai wrote: > > On Mon, 23 Apr 2018 14:05:52 +0200, > > Paul Menzel wrote: > >> > >> From: Paul Menzel > >> Date: Sat, 24 Mar 2018 09:28:43 +0100 > >> > >> On an ASRock E350M1, with Linux 4.17-rc1 according to `initcall_debug` > >> calling `azx_driver_init` takes sometimes more than a few milliseconds, > >> and up to 200 ms. > >> > >> ``` > >> [ 2.892598] calling azx_driver_init+0x0/0xfe4 [snd_hda_intel] @ 218 > >> [ 2.943002] initcall azx_driver_init+0x0/0xfe4 [snd_hda_intel] > >> returned 0 after 49195 usecs > >> ``` > >> > >> Trying to execute the Linux kernel in less than 500 ms, this is quite a > >> hold-up, and therefore request the probe from an async task. > >> > >> With this change, the test shows, that the function returns earlier. > >> > >> ``` > >> [ 3.254800] calling azx_driver_init+0x0/0xfe4 [snd_hda_intel] @ 227 > >> [ 3.254887] initcall azx_driver_init+0x0/0xfe4 [snd_hda_intel] > >> returned 0 after 66 usecs > >> ``` > >> > >> The same behavior is visible on a Dell OptiPlex 7010. The longer times > >> seem to happen, when the module *e1000e* is probed during the same time. > >> > >> Signed-off-by: Paul Menzel > > > > What actually took so long? Could you analyze further instead of > > blindly putting the flag? > > Well, I am not sure. Could you please give me hints, how to debug this > further? Is there some debug flag? Usually perf would help, but even a simple printk() should suffice to see what's going on there :) > I am only aware of the Ftrace framework, but in my experience it also > skews the timings quite a bit, so might not be the best choice. We know that there are some cases where the codec / controller communication stalls on the recent Coffee Lake or such platforms. But quite not sure how it happens. Moving the stuff into async just moves something ugly, and it's no fix, per se, if such a long delay itself is unexpected. thanks, Takashi