From owner-freebsd-current@freebsd.org Fri Dec 2 05:39:46 2016 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 47C16C61F71 for ; Fri, 2 Dec 2016 05:39:46 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: from mailman.ysv.freebsd.org (unknown [127.0.1.3]) by mx1.freebsd.org (Postfix) with ESMTP id 271631D49 for ; Fri, 2 Dec 2016 05:39:46 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: by mailman.ysv.freebsd.org (Postfix) id 266D7C61F70; Fri, 2 Dec 2016 05:39:46 +0000 (UTC) Delivered-To: current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 260A0C61F6F for ; Fri, 2 Dec 2016 05:39:46 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: from mail-ua0-x236.google.com (mail-ua0-x236.google.com [IPv6:2607:f8b0:400c:c08::236]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id D3FE01D48; Fri, 2 Dec 2016 05:39:45 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: by mail-ua0-x236.google.com with SMTP id 20so271459647uak.0; Thu, 01 Dec 2016 21:39:45 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=7U5FP4en8wqv3+F9JOy84W0ususdXgENa4zsefdrv5w=; b=c2oaGxv4VvXTePycDz7dKu3RmsBfIkbsCuz0O6imAZ+RE8FQr0RfVpXdFR+ggTGb09 ipfHMJV8D/Ce7HztEMQqWaRxFnJ5rUzj5PVa0Y7YA6jKwWu77Sp6SdOmBPZ5YSCCWUdi K7kI9Jel4Nrrxma1XeKe6HaxVU7qUesXOqHH1TGNS97sY4fbMEn6n6L/rm3EhOGH/NYS 3cTb+qUNSLypg8xA9Nsfpo+hfGF5W+scHcvlswskvs0/5c+zZo10ftqIezD0hMvoOj0m mTxDpxic//37ofSsD6la/gp1RWMK+hBzJVT+qqefwZk0Ccn3/Ku2SK96ZHHW169ToyYA Hfow== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=7U5FP4en8wqv3+F9JOy84W0ususdXgENa4zsefdrv5w=; b=a/duY7S7B27oUJDdFD4RESIe3AsOsLUe7G6+ohrkUIQUaTMZrRqwnaGUzv1o16aJ5m R5JqTP+p0SJPkPycFIwaRflNsTw/MAshIVXP8eluTpCBySrkl7JUNPscopJPcYGf8lfL w9o2pvbJI8mr8+CCzAXFOgod4vxcgq8FhKWQ+BjLZIrL5ZPJplzy16wpnoxVWQMMyfqi 5M8FDnzXoaCxfE4rGw5IsMiOJy86XEZ5x6MYLVEiHQ15O7YA63jw+lJdRizi0oOYOu2D vnyTjC3x/4fQw5Zac8CTUtft1nOKgsKfUjA/yXk+9TICYRSQJ9WxHUX1+q3BQO6wKJoF h3rA== X-Gm-Message-State: AKaTC02Gbcq0gOTsy6mCWYRhy7jYVOOGlLVAWLeILMRalVHyAa2nkjTOOIF9iZjiqI3V9y4xsnMkM3HHtcoCvw== X-Received: by 10.176.65.167 with SMTP id 36mr21574607uap.175.1480657184763; Thu, 01 Dec 2016 21:39:44 -0800 (PST) MIME-Version: 1.0 Received: by 10.176.5.198 with HTTP; Thu, 1 Dec 2016 21:39:44 -0800 (PST) In-Reply-To: References: <7005233.xZtqgRZ2t6@ralph.baldwin.cx> <2914745.0k996KCSkq@ralph.baldwin.cx> From: Sepherosa Ziehau Date: Fri, 2 Dec 2016 13:39:44 +0800 Message-ID: Subject: Re: Please test EARLY_AP_STARTUP To: John Baldwin Cc: "freebsd-current@freebsd.org" Content-Type: text/plain; charset=UTF-8 X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 02 Dec 2016 05:39:46 -0000 On Fri, Dec 2, 2016 at 12:53 PM, Sepherosa Ziehau wrote: > On Fri, Dec 2, 2016 at 1:49 AM, John Baldwin wrote: >> On Thursday, December 01, 2016 01:53:29 PM Sepherosa Ziehau wrote: >>> On Wed, Nov 30, 2016 at 9:59 AM, Sepherosa Ziehau wrote: >>> >>> After fdc is disabled and hyperv/storvsc is fixed, it seems to boot >>> >>> fine, except a long delay (28~30seconds) here: >>> >>> .... >>> >>> Timecounters tick every 1.000 msec >>> >>> ----- >>> >>> 28 ~ 30 seconds delay >>> >>> ----- >>> >>> vlan: initialized, using hash tables with chaining >>> >>> .... >>> >>> >>> >>> I have the bootverbose dmesg here: >>> >>> https://people.freebsd.org/~sephe/dmesg_earlyap.txt >>> >>> >>> >>> I booted 10 times, only one boot does not suffer this 30 seconds >>> >>> delay. It sounds like some races to me. Any hints? >>> >> >>> >> It is likely a race as we start running things sooner now, yes. Can you >>> >> break into DDB during the hang and see what thread0 is waiting on? If >>> >> it is in the interrupt hooks you can use 'show conifhk' in DDB to see the >>> >> list of pending interrupt hooks. That provides a list of candidate drivers >>> >> to inspect (e.g. stack traces of relevant kthreads) for what is actually >>> >> waiting (and what it is waiting on) >>> > >>> > Just tried, but I failed to break into DDB during the 30 seconds >>> > delay. DDB was entered after the 30 seconds delay, though I press the >>> > break key when the delay started. >>> >>> I tried add VERBOSE_SYSINIT option in order to get a rough location of >>> this delay, but the system boots just fine w/ VERBOSE_SYSINIT option, >>> sigh. >> >> You could add KTR_PROC tracing and use 'show ktr' in DDB when you break in after the >> 30 second delay to see what it was doing during the delay perhaps? > > I have narrowed it down by patching the VERBOSE_SYSINIT: the > kthread_start(&deadlkres_kd) introduces the 30 seconds delay, i.e. > SYSINIT(deadlkres, SI_SUB_CLOCKS, SI_ORDER_ANY, kthread_start, > &deadlkres_kd) blocks for 30 seconds. I commented out the DEADLKRES option, now the delay happens randomly, sometimes even before a VERBOSE_SYSINIT entry logging. But the delay always happens after inittimecounter(0), and before the SI_SUB_INT_CONFIG_HOOKS. I didn't notice useful information from DDB 'show ktr', once it thawed. Anything I should be aware of in the KTR_PROC ktrlog? Thanks, sephe -- Tomorrow Will Never Die