Process timing issue

[Ryan Stone]

To debug weird scheduling issues I find it helpful to start by looking
at a schedgraph.  schedgraph is a tool that can display a graphical
representation of what the scheduler was doing over a small slice of
time.  The one downside is that you have to recompile your kernel to
get the hooks that collect the necessary data, but it sounds like your
problem is pretty easy to reproduce and so that shouldn't be a big
problem.

To enable the hooks, put the following in your kernel conf:

options KTR
options KTR_COMPILE=KTR_SCHED
options KTR_MASK=KTR_SCHED
options KTR_ENTIRES=(128*1024)

Then rebuild and install the new kernel.  Next, run your test.  The
instant that your test has detected the long delay, set the sysctl
debug.ktr.mask to 0.  The scheduler hooks record data into a ring
buffer, so the interesting data can be flushed out within seconds.
Clearing that sysctl will stop any further events from being logged,
which means that the interesting data will stay there until you go and
collect it.

You can get the raw data by redirecting the output of "ktrdump -ct"
into a file.  Then from any machine with a graphical interface(FreeBSD
with X installed, Windows, Mac, whatever) and python installed, run:
$ python schedgraph.py /path/to/ktrdump/output

You can get schedgraph.py from /usr/src/tools/sched.

If you want to collect the data again, set the sysctl debug.ktr.mask
back to 0x20000000 to restart gathering scheduler data.

Ryan