Date: Sat, 21 Apr 2012 16:52:06 +0200 From: Fabian Keil <freebsd-listen@fabiankeil.de> To: freebsd-hackers@freebsd.org Subject: Re: [PATCH] Implementation of DTrace sched provider (with bonus schedgraph script) Message-ID: <20120421165206.0da0cf88@fabiankeil.de> In-Reply-To: <20120420153443.207738a3.fk@fabiankeil.de> References: <CAFMmRNzRN1GHDCVPPvfzR101bTS8-5KagmXZLADjifnJ-YG7Ww@mail.gmail.com> <20120420153443.207738a3.fk@fabiankeil.de>
next in thread | previous in thread | raw e-mail | index | archive | help
--Sig_/q/oReAtiOu7WW18Sldvm2JU Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable Fabian Keil <fk@fabiankeil.de> wrote: > Ryan Stone <rysto32@gmail.com> wrote: >=20 > > I've implemented the sched provider for FreeBSD. This provider > > provides probes that fire when various scheduling decisions are made. >=20 > 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: durati= on: 126.85ms, prio: 104, linkedto: emacs/emacs tid 100463 running Xorg/Xorg tid 100463 on: cpu0 at: 3665070552032 attributes: duratio= n: 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: d= uration: 494.09us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066533938 attributes: dura= tion: 5.33us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066544595 attributes: d= uration: 120.16us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066797747 attributes: d= uration: 55.47us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066908687 attributes: dura= tion: 9.20us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665066933464 attributes: dura= tion: 79.03us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067091530 attributes: d= uration: 29.19us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067560848 attributes: d= uration: 106.72us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067774292 attributes: dura= tion: 5.49us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665067785275 attributes: d= uration: 376.84us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068538958 attributes: dura= tion: 5.35us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068585628 attributes: d= uration: 63.05us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068711726 attributes: dura= tion: 7.69us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665068727114 attributes: d= uration: 278.78us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069297929 attributes: d= uration: 56.36us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069410643 attributes: dura= tion: 8.05us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069435720 attributes: dura= tion: 6.04us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069447800 attributes: d= uration: 45.15us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069538099 attributes: dura= tion: 11.23us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665069560564 attributes: d= uration: 487.04us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070534639 attributes: dura= tion: 5.37us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070549009 attributes: dura= tion: 52.97us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665070654952 attributes: d= uration: 439.71us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071545318 attributes: d= uration: 56.78us, prio: 255 running idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071672443 attributes: d= uration: 55.40us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071783233 attributes: dura= tion: 9.17us, prio: 255 idle idle/idle: cpu0 tid 100003 on: cpu0 at: 3665071808741 attributes: dura= tion: 83.01us, prio: 255 ----- running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665065783769 attributes: d= uration: 244.57us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066283934 attributes: d= uration: 244.74us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066790594 attributes: d= uration: 53.57us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066914236 attributes: d= uration: 3.49us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665066921213 attributes: dura= tion: 22.79us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665067019387 attributes: dura= tion: 27.54us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665067077581 attributes: dura= tion: 820.16us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068717906 attributes: d= uration: 27.57us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068773053 attributes: dura= tion: 5.73us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665068784511 attributes: d= uration: 244.42us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069290295 attributes: d= uration: 54.13us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069420973 attributes: dura= tion: 10.37us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069441715 attributes: d= uration: 40.54us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069522796 attributes: dura= tion: 11.24us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069545272 attributes: d= uration: 51.42us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665069658978 attributes: d= uration: 244.65us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070159073 attributes: d= uration: 188.70us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070554778 attributes: d= uration: 46.80us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665070659047 attributes: d= uration: 244.40us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071147838 attributes: dura= tion: 5.52us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071158871 attributes: d= uration: 244.48us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071647827 attributes: dura= tion: 8.30us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071664429 attributes: d= uration: 54.08us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071795945 attributes: dura= tion: 23.26us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071853402 attributes: dura= tion: 22.81us, prio: 255 running idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071899015 attributes: d= uration: 3.15us, prio: 255 idle idle/idle: cpu1 tid 100004 on: cpu1 at: 3665071905311 attributes: dura= tion: 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 --Sig_/q/oReAtiOu7WW18Sldvm2JU Content-Type: application/pgp-signature; name=signature.asc Content-Disposition: attachment; filename=signature.asc -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.19 (FreeBSD) iEYEARECAAYFAk+SyZkACgkQBYqIVf93VJ3rCwCgzWIpCJzrclwqaI8+yXYVQeFO HyMAn3FL5R+sSL6IP7tLecfKBpuZgJXn =aHMF -----END PGP SIGNATURE----- --Sig_/q/oReAtiOu7WW18Sldvm2JU--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20120421165206.0da0cf88>