[PATCH] Implementation of DTrace sched provider (with bonus schedgraph script)

[Fabian Keil]

Fabian Keil <fk at fabiankeil.de> wrote:

> Ryan Stone <rysto32 at gmail.com> wrote:
> 
> > I've implemented the sched provider for FreeBSD.  This provider
> > provides probes that fire when various scheduling decisions are made.
> 
> Thanks a lot. Works for me (so far) with HEAD on amd64.

The following seems strange to me:

runq add Xorg/Xorg tid 100463 on: cpu0 at: 3664816837528 attributes: duration: 126.85ms, prio: 104, linkedto: emacs/emacs tid 100463
running Xorg/Xorg tid 100463 on: cpu0 at: 3665070552032 attributes: duration: 49.00us, prio: 120

It seems to imply that the thread had to wait 126.85ms
so it could run for 49.00us. While it waited for cpu time,
both cpu cores spent a lot more than 49.00us being idle:

--------
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665065545759 attributes: duration: 494.09us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066533938 attributes: duration: 5.33us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066544595 attributes: duration: 120.16us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066797747 attributes: duration: 55.47us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066908687 attributes: duration: 9.20us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066933464 attributes: duration: 79.03us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067091530 attributes: duration: 29.19us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067560848 attributes: duration: 106.72us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067774292 attributes: duration: 5.49us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067785275 attributes: duration: 376.84us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068538958 attributes: duration: 5.35us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068585628 attributes: duration: 63.05us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068711726 attributes: duration: 7.69us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068727114 attributes: duration: 278.78us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069297929 attributes: duration: 56.36us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069410643 attributes: duration: 8.05us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069435720 attributes: duration: 6.04us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069447800 attributes: duration: 45.15us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069538099 attributes: duration: 11.23us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069560564 attributes: duration: 487.04us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070534639 attributes: duration: 5.37us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070549009 attributes: duration: 52.97us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070654952 attributes: duration: 439.71us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071545318 attributes: duration: 56.78us, prio: 255
running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071672443 attributes: duration: 55.40us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071783233 attributes: duration: 9.17us, prio: 255
idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071808741 attributes: duration: 83.01us, prio: 255
-----
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665065783769 attributes: duration: 244.57us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066283934 attributes: duration: 244.74us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066790594 attributes: duration: 53.57us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066914236 attributes: duration: 3.49us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066921213 attributes: duration: 22.79us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665067019387 attributes: duration: 27.54us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665067077581 attributes: duration: 820.16us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068717906 attributes: duration: 27.57us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068773053 attributes: duration: 5.73us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068784511 attributes: duration: 244.42us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069290295 attributes: duration: 54.13us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069420973 attributes: duration: 10.37us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069441715 attributes: duration: 40.54us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069522796 attributes: duration: 11.24us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069545272 attributes: duration: 51.42us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069658978 attributes: duration: 244.65us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070159073 attributes: duration: 188.70us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070554778 attributes: duration: 46.80us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070659047 attributes: duration: 244.40us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071147838 attributes: duration: 5.52us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071158871 attributes: duration: 244.48us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071647827 attributes: duration: 8.30us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071664429 attributes: duration: 54.08us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071795945 attributes: duration: 23.26us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071853402 attributes: duration: 22.81us, prio: 255
running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071899015 attributes: duration: 3.15us, prio: 255
idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071905311 attributes: duration: 845.12us, prio: 255

Spending cpu time on idle when there's actual work to be done
makes no sense to me. I'm not too familiar with sched_ule and
schedgraph.py, though, so I'm wondering if I'm interpreting this
correctly?

Fabian
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 196 bytes
Desc: not available
Url : http://lists.freebsd.org/pipermail/freebsd-hackers/attachments/20120421/d13b1386/signature.pgp