Re: confusing KTR_SCHED traces

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