move thread switch tracing from mi_switch to sched_switch

This is done so that the thread state changes during the switch
are not confused with the thread state changes reported when the thread
spins on a lock.

Here is 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

The above trace could leave an impression that the final state of
the thread was "running".
After this change the sleep state will be reported after the "spinning"
and "running" states reported for the sched lock.

Reviewed by:	jhb, markj
MFC after:	1 week
Sponsored by:	Panzura
Differential Revision: https://reviews.freebsd.org/D9961
This commit is contained in:
Andriy Gapon 2017-03-23 08:57:04 +00:00
parent 396e94586a
commit afa0a46cfd
4 changed files with 34 additions and 19 deletions

View File

@ -66,13 +66,6 @@ __FBSDID("$FreeBSD$");
#include <machine/cpu.h>
#define KTDSTATE(td) \
(((td)->td_inhibitors & TDI_SLEEPING) != 0 ? "sleep" : \
((td)->td_inhibitors & TDI_SUSPENDED) != 0 ? "suspended" : \
((td)->td_inhibitors & TDI_SWAPPED) != 0 ? "swapped" : \
((td)->td_inhibitors & TDI_LOCK) != 0 ? "blocked" : \
((td)->td_inhibitors & TDI_IWAIT) != 0 ? "iwait" : "yielding")
static void synch_setup(void *dummy);
SYSINIT(synch_setup, SI_SUB_KICK_SCHEDULER, SI_ORDER_FIRST, synch_setup,
NULL);
@ -437,20 +430,8 @@ mi_switch(int flags, struct thread *newtd)
PCPU_SET(switchticks, ticks);
CTR4(KTR_PROC, "mi_switch: old thread %ld (td_sched %p, pid %ld, %s)",
td->td_tid, td_get_sched(td), td->td_proc->p_pid, td->td_name);
#if (KTR_COMPILE & KTR_SCHED) != 0
if (TD_IS_IDLETHREAD(td))
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "idle",
"prio:%d", td->td_priority);
else
KTR_STATE3(KTR_SCHED, "thread", sched_tdname(td), KTDSTATE(td),
"prio:%d", td->td_priority, "wmesg:\"%s\"", td->td_wmesg,
"lockname:\"%s\"", td->td_lockname);
#endif
SDT_PROBE0(sched, , , preempt);
sched_switch(td, newtd, flags);
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "running",
"prio:%d", td->td_priority);
CTR4(KTR_PROC, "mi_switch: new thread %ld (td_sched %p, pid %ld, %s)",
td->td_tid, td_get_sched(td), td->td_proc->p_pid, td->td_name);

View File

@ -1013,6 +1013,16 @@ sched_switch(struct thread *td, struct thread *newtd, int flags)
MPASS(newtd->td_lock == &sched_lock);
}
#if (KTR_COMPILE & KTR_SCHED) != 0
if (TD_IS_IDLETHREAD(td))
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "idle",
"prio:%d", td->td_priority);
else
KTR_STATE3(KTR_SCHED, "thread", sched_tdname(td), KTDSTATE(td),
"prio:%d", td->td_priority, "wmesg:\"%s\"", td->td_wmesg,
"lockname:\"%s\"", td->td_lockname);
#endif
if (td != newtd) {
#ifdef HWPMC_HOOKS
if (PMC_PROC_IS_USING_PMCS(td->td_proc))
@ -1061,6 +1071,9 @@ sched_switch(struct thread *td, struct thread *newtd, int flags)
} else
SDT_PROBE0(sched, , , remain__cpu);
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "running",
"prio:%d", td->td_priority);
#ifdef SMP
if (td->td_flags & TDF_IDLETD)
CPU_SET(PCPU_GET(cpuid), &idle_cpus_mask);

View File

@ -1938,6 +1938,17 @@ sched_switch(struct thread *td, struct thread *newtd, int flags)
mtx = thread_lock_block(td);
tdq_load_rem(tdq, td);
}
#if (KTR_COMPILE & KTR_SCHED) != 0
if (TD_IS_IDLETHREAD(td))
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "idle",
"prio:%d", td->td_priority);
else
KTR_STATE3(KTR_SCHED, "thread", sched_tdname(td), KTDSTATE(td),
"prio:%d", td->td_priority, "wmesg:\"%s\"", td->td_wmesg,
"lockname:\"%s\"", td->td_lockname);
#endif
/*
* We enter here with the thread blocked and assigned to the
* appropriate cpu run-queue or sleep-queue and with the current
@ -1988,6 +1999,10 @@ sched_switch(struct thread *td, struct thread *newtd, int flags)
thread_unblock_switch(td, mtx);
SDT_PROBE0(sched, , , remain__cpu);
}
KTR_STATE1(KTR_SCHED, "thread", sched_tdname(td), "running",
"prio:%d", td->td_priority);
/*
* Assert that all went well and return.
*/

View File

@ -488,6 +488,12 @@ do { \
#define TD_ON_UPILOCK(td) ((td)->td_flags & TDF_UPIBLOCKED)
#define TD_IS_IDLETHREAD(td) ((td)->td_flags & TDF_IDLETD)
#define KTDSTATE(td) \
(((td)->td_inhibitors & TDI_SLEEPING) != 0 ? "sleep" : \
((td)->td_inhibitors & TDI_SUSPENDED) != 0 ? "suspended" : \
((td)->td_inhibitors & TDI_SWAPPED) != 0 ? "swapped" : \
((td)->td_inhibitors & TDI_LOCK) != 0 ? "blocked" : \
((td)->td_inhibitors & TDI_IWAIT) != 0 ? "iwait" : "yielding")
#define TD_SET_INHIB(td, inhib) do { \
(td)->td_state = TDS_INHIBITED; \