From owner-freebsd-current@freebsd.org Fri Dec 2 04:53:04 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 9FCDDC5EF5C for ; Fri, 2 Dec 2016 04:53:04 +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 7FF6F13C3 for ; Fri, 2 Dec 2016 04:53:04 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: by mailman.ysv.freebsd.org (Postfix) id 7C809C5EF5B; Fri, 2 Dec 2016 04:53:04 +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 7A721C5EF5A for ; Fri, 2 Dec 2016 04:53:04 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: from mail-ua0-x22d.google.com (mail-ua0-x22d.google.com [IPv6:2607:f8b0:400c:c08::22d]) (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 2917B13C2; Fri, 2 Dec 2016 04:53:04 +0000 (UTC) (envelope-from sepherosa@gmail.com) Received: by mail-ua0-x22d.google.com with SMTP id 12so270902642uas.2; Thu, 01 Dec 2016 20:53:04 -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=s/0bsfqaA4ap70pwKzZHqiFI4psBNX8I4r8ZSY/SFv4=; b=UvJIPHhOaPcE0vJD/k1QqcfU9Chc6RJO0KqgZVYLi7VUjq7KM0bmeV0v1eGxUtbYnS xf9PfvENqONLz7O2IOnPUO43lgAFnunXlgCO6pOHYfzcNhaZlHy7zOm3L4W1dlatPbl+ H8FkMkKRiKPyiX5aaTOQiMcN6lUBcIhDgIE2e3xqBX7F3Z2nflJkbu/ixwHNOyM+V0V1 8dqD/erSMkDYcUXolZSSCmL8faHC14MmkcQLyCOvJwxDAnlQQ6WbX5FbTmmj/Yb1muWs t6p4MVIft9EwPlOR/oPjV7+ZwgifHy18Kf9V1perfu492uKNlaTxcg5Y9kmhzGQ/6jri wfoA== 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=s/0bsfqaA4ap70pwKzZHqiFI4psBNX8I4r8ZSY/SFv4=; b=NpoNr6HzpcgmRNjJ1oZvOtq99T7XkrvpNN5su3w4mySVn7Mcriyl2hFbOInxMtNWjw AJg5bv4GwFo9aItOKzYjJ81ye4H67lxCYNmFRo9+bDgecQLMVYtmY8SoOZ0d6mwx0Mom Li/X/9IxPE2hUgmObN9pOBBdNXRZaEn3KNs05aXVJXsoS+gt/VrN7jbNYdyLe7S0ytLX zX/79yQ+TAy7XW0xIEv0fb8jWQslUnKlFHvbkABFfpig+MJU/6unUW+uVzd6nSAaz6vf AazYl8jnp51teYgRhlhxgEck0DvoMgChNAeegBmxCKYhrZv6aGs8bwfHOpkB5iseM+Yy pn9Q== X-Gm-Message-State: AKaTC01GlYnbdEdMyyRKL/RESFuYSATEL132JSlxx0G8MFsFA0/COT+ijJXsHeJXxfwgjJe5Fai/MCiR1f2R9Q== X-Received: by 10.159.55.168 with SMTP id q37mr32532736uaq.63.1480654382967; Thu, 01 Dec 2016 20:53:02 -0800 (PST) MIME-Version: 1.0 Received: by 10.176.5.198 with HTTP; Thu, 1 Dec 2016 20:53:02 -0800 (PST) In-Reply-To: <2914745.0k996KCSkq@ralph.baldwin.cx> References: <7005233.xZtqgRZ2t6@ralph.baldwin.cx> <2914745.0k996KCSkq@ralph.baldwin.cx> From: Sepherosa Ziehau Date: Fri, 2 Dec 2016 12:53:02 +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 04:53:04 -0000 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. Thanks, sephe -- Tomorrow Will Never Die