From owner-freebsd-current@freebsd.org Fri Feb 17 18:50:02 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 CC5D9CE23B3 for ; Fri, 17 Feb 2017 18:50:02 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from citapm.icyb.net.ua (citapm.icyb.net.ua [212.40.38.140]) by mx1.freebsd.org (Postfix) with ESMTP id B753E1684; Fri, 17 Feb 2017 18:50:01 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from porto.starpoint.kiev.ua (porto-e.starpoint.kiev.ua [212.40.38.100]) by citapm.icyb.net.ua (8.8.8p3/ICyb-2.3exp) with ESMTP id UAA11575; Fri, 17 Feb 2017 20:49:53 +0200 (EET) (envelope-from avg@FreeBSD.org) Received: from localhost ([127.0.0.1]) by porto.starpoint.kiev.ua with esmtp (Exim 4.34 (FreeBSD)) id 1cenbN-000H9T-IK; Fri, 17 Feb 2017 20:49:53 +0200 To: FreeBSD Current From: Andriy Gapon Subject: confusing KTR_SCHED traces Message-ID: Date: Fri, 17 Feb 2017 20:48:57 +0200 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:45.0) Gecko/20100101 Thunderbird/45.6.0 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 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 List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 17 Feb 2017 18:50:02 -0000 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. Any suggestions are welcome. Thanks! -- Andriy Gapon