From owner-freebsd-current@freebsd.org  Wed Mar  1 09:17:35 2017
Return-Path: <owner-freebsd-current@freebsd.org>
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 4809FCF3394
 for <freebsd-current@mailman.ysv.freebsd.org>;
 Wed,  1 Mar 2017 09:17:35 +0000 (UTC)
 (envelope-from julian@freebsd.org)
Received: from vps1.elischer.org (vps1.elischer.org [204.109.63.16])
 (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
 (Client CN "vps1.elischer.org",
 Issuer "CA Cert Signing Authority" (not verified))
 by mx1.freebsd.org (Postfix) with ESMTPS id 27534828
 for <freebsd-current@freebsd.org>; Wed,  1 Mar 2017 09:17:34 +0000 (UTC)
 (envelope-from julian@freebsd.org)
Received: from Julian-MBP3.local (220-253-188-71.dyn.iinet.net.au
 [220.253.188.71]) (authenticated bits=0)
 by vps1.elischer.org (8.15.2/8.15.2) with ESMTPSA id v219HTq1018628
 (version=TLSv1.2 cipher=DHE-RSA-AES128-SHA bits=128 verify=NO)
 for <freebsd-current@freebsd.org>; Wed, 1 Mar 2017 01:17:33 -0800 (PST)
 (envelope-from julian@freebsd.org)
Subject: Re: confusing KTR_SCHED traces
To: freebsd-current@freebsd.org
References: <e45fe46f-5431-dd3a-f688-9b34dad30d4f@FreeBSD.org>
From: Julian Elischer <julian@freebsd.org>
Message-ID: <b4a40505-36af-ed4e-7606-1fa8c7fe602b@freebsd.org>
Date: Wed, 1 Mar 2017 17:17:24 +0800
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:45.0)
 Gecko/20100101 Thunderbird/45.7.1
MIME-Version: 1.0
In-Reply-To: <e45fe46f-5431-dd3a-f688-9b34dad30d4f@FreeBSD.org>
Content-Type: text/plain; charset=windows-1252; format=flowed
Content-Transfer-Encoding: 7bit
X-BeenThere: freebsd-current@freebsd.org
X-Mailman-Version: 2.1.23
Precedence: list
List-Id: Discussions about the use of FreeBSD-current
 <freebsd-current.freebsd.org>
List-Unsubscribe: <https://lists.freebsd.org/mailman/options/freebsd-current>, 
 <mailto:freebsd-current-request@freebsd.org?subject=unsubscribe>
List-Archive: <http://lists.freebsd.org/pipermail/freebsd-current/>
List-Post: <mailto:freebsd-current@freebsd.org>
List-Help: <mailto:freebsd-current-request@freebsd.org?subject=help>
List-Subscribe: <https://lists.freebsd.org/mailman/listinfo/freebsd-current>, 
 <mailto:freebsd-current-request@freebsd.org?subject=subscribe>
X-List-Received-Date: Wed, 01 Mar 2017 09:17:35 -0000

On 18/2/17 2:48 am, 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 that is the way to fix it
>
> Any suggestions are welcome.
> Thanks!