From owner-freebsd-current@freebsd.org Sat Mar 4 18:53:57 2017 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 738E6CF8E82 for ; Sat, 4 Mar 2017 18:53:57 +0000 (UTC) (envelope-from jhb@freebsd.org) Received: from mail.baldwin.cx (bigwig.baldwin.cx [IPv6:2001:470:1f11:75::1]) (using TLSv1 with cipher DHE-RSA-CAMELLIA256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 49C52175F; Sat, 4 Mar 2017 18:53:57 +0000 (UTC) (envelope-from jhb@freebsd.org) Received: from ralph.baldwin.cx (c-73-231-226-104.hsd1.ca.comcast.net [73.231.226.104]) by mail.baldwin.cx (Postfix) with ESMTPSA id 8803910A7B9; Sat, 4 Mar 2017 13:53:55 -0500 (EST) From: John Baldwin To: freebsd-current@freebsd.org Cc: Andriy Gapon , FreeBSD Current Subject: Re: confusing KTR_SCHED traces Date: Sat, 04 Mar 2017 09:13:46 -0800 Message-ID: <3582744.LcvQFR8qML@ralph.baldwin.cx> User-Agent: KMail/4.14.10 (FreeBSD/11.0-STABLE; KDE/4.14.10; amd64; ; ) In-Reply-To: References: MIME-Version: 1.0 Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii" X-Greylist: Sender succeeded SMTP AUTH, not delayed by milter-greylist-4.4.3 (mail.baldwin.cx); Sat, 04 Mar 2017 13:53:55 -0500 (EST) X-Virus-Scanned: clamav-milter 0.99.2 at mail.baldwin.cx X-Virus-Status: Clean 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: Sat, 04 Mar 2017 18:53:57 -0000 On Friday, February 17, 2017 08:48:57 PM Andriy Gapon wrote: > > First, an example, three consecutive entries for the same thread (from top to > bottom): > KTRGRAPH group:"thread", id:"zio_write_intr_3 tid 100260", state:"sleep", > attributes: prio:84, wmesg:"-", lockname:"(null)" > KTRGRAPH group:"thread", id:"zio_write_intr_3 tid 100260", state:"spinning", > attributes: lockname:"sched lock 1" > KTRGRAPH group:"thread", id:"zio_write_intr_3 tid 100260", state:"running", > attributes: none > > Any automatic analysis tool including schedgraph.py will assume that the thread > ends up in the running state. In reality, of course, the thread is in the > sleeping state. > The confusing trace is a result of logging the thread's intention to switch out > in mi_switch() before calling sched_switch(). In ULE's sched_switch() we > acquire the "TDQ_LOCK" which could be contested. In that case the thread spins > waiting for the lock to be released. This is reported as "spinning" and then > "running" states. > > I would like to fix that, but not sure how to do that best. > One idea is to move the mi_switch() trace closer to the cpu_switch() call > similarly to DTrace sched:cpu-off and sched:cpu-on probes. I think this is the right fix. -- John Baldwin