From owner-freebsd-current@freebsd.org Tue Oct 22 13:16:41 2019 Return-Path: Delivered-To: freebsd-current@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id BE7F515A638 for ; Tue, 22 Oct 2019 13:16:41 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from kib.kiev.ua (kib.kiev.ua [IPv6:2001:470:d5e7:1::1]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) server-signature RSA-PSS (4096 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 46yDYP3WQDz3G6D; Tue, 22 Oct 2019 13:16:41 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from tom.home (kib@localhost [127.0.0.1]) by kib.kiev.ua (8.15.2/8.15.2) with ESMTPS id x9MDGX0V078621 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO); Tue, 22 Oct 2019 16:16:36 +0300 (EEST) (envelope-from kostikbel@gmail.com) DKIM-Filter: OpenDKIM Filter v2.10.3 kib.kiev.ua x9MDGX0V078621 Received: (from kostik@localhost) by tom.home (8.15.2/8.15.2/Submit) id x9MDGXtu078620; Tue, 22 Oct 2019 16:16:33 +0300 (EEST) (envelope-from kostikbel@gmail.com) X-Authentication-Warning: tom.home: kostik set sender to kostikbel@gmail.com using -f Date: Tue, 22 Oct 2019 16:16:33 +0300 From: Konstantin Belousov To: Andriy Gapon Cc: FreeBSD Current Subject: Re: thread on sleepqueue does not wake up after timeout Message-ID: <20191022131633.GN73312@kib.kiev.ua> References: <20191022104434.GM73312@kib.kiev.ua> <3a67f9a9-31cf-5814-4a68-8bdd6063b21e@FreeBSD.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <3a67f9a9-31cf-5814-4a68-8bdd6063b21e@FreeBSD.org> User-Agent: Mutt/1.12.2 (2019-09-21) X-Spam-Status: No, score=-1.0 required=5.0 tests=ALL_TRUSTED,BAYES_00, DKIM_ADSP_CUSTOM_MED,FORGED_GMAIL_RCVD,FREEMAIL_FROM, NML_ADSP_CUSTOM_MED autolearn=no autolearn_force=no version=3.4.2 X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on tom.home X-Rspamd-Queue-Id: 46yDYP3WQDz3G6D X-Spamd-Bar: ----- Authentication-Results: mx1.freebsd.org; none X-Spamd-Result: default: False [-5.97 / 15.00]; NEURAL_HAM_MEDIUM(-0.97)[-0.970,0]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; REPLY(-4.00)[] X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.29 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: Tue, 22 Oct 2019 13:16:41 -0000 On Tue, Oct 22, 2019 at 02:48:56PM +0300, Andriy Gapon wrote: > On 22/10/2019 13:44, Konstantin Belousov wrote: > > On Tue, Oct 22, 2019 at 01:08:59PM +0300, Andriy Gapon wrote: > >> > >> We observe a problem that happens very rarely (about once a month across many > >> test machines). The problem is that a thread remain in sleepq_timedwait() even > >> after its timeout expires. The thread's td_slpcallout looks like the callout > >> has fired. But the thread's state looks like it was never notified. > >> E.g.: > >> (kgdb) p td->td_slpcallout > >> $1 = {c_links = {le = {le_next = 0xfffff800108e6470, le_prev = > >> 0xfffffe0000be6ea8}, sle = {sle_next = 0xfffff800108e6470}, tqe = {tqe_next = > >> 0xfffff800108e6470, tqe_prev = 0xfffffe0000be6ea8}}, c_time = 160957479343159, > >> c_precision = 268435450, c_arg = 0xfffff80184602000, c_func = > >> 0xffffffff807481d0 , c_lock = 0x0, c_flags = 2, c_iflags = 272, > >> c_cpu = 6, c_exec_time = 160957506517070} [*] > >> (kgdb) p/x td->td_flags > >> $5 = 0x80000004 > > What is the bit 31 in your flags ? FreeBSD does not use the bit. > > It's TDF_NOSWAP, a local addition. > We use it to prohibit full process swapout (I guess that means kernel stacks). > > >> (kgdb) p td->td_sqqueue > >> $8 = 0 > >> (kgdb) p td->td_sleepqueue > >> $9 = (struct sleepqueue *) 0x0 > >> (kgdb) p td->td_wchan > >> $10 = (void *) 0xfffff802b990df38 > >> > >> > >> Has anyone seen anything like this problem? > > Yes, but it was very long time ago. See r303426. > > Yeah, we are based off r329000 plus a bunch of merges for various fixes. > One thing I forgot to mention is that it seems to happen only on VMware guests, > but maybe it's only because we have many more virtual test boxes than we have > physical ones. > One thing I suspected was that binuptime() could somehow jump backwards... Do you use any of suspend/migration ? Perhaps record sbinuptime() in the struct thread in sleepq_timeout() and keep the original value of td_sleeptimo around to see what did happen. > > >> Any advice on how to diagnose it? > >> > >> Thanks! > >> > >> P.S. > >> c_exec_time is our addition, we set this field right before firing a callback > >> and we reset it to zero when a callout is (re-)scheduled. > > > -- > Andriy Gapon