From mboxrd@z Thu Jan 1 00:00:00 1970 From: Dario Faggioli Subject: Re: [PATCH] xen: sched: improve debug dump output. Date: Thu, 26 Jan 2017 23:08:41 +0100 Message-ID: <1485468521.32103.204.camel@citrix.com> References: <148544957013.26566.1886390191777485188.stgit@Solace.fritz.box> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="===============5532185191276083715==" Return-path: Received: from mail6.bemta6.messagelabs.com ([193.109.254.103]) by lists.xenproject.org with esmtp (Exim 4.84_2) (envelope-from ) id 1cWsDr-000357-14 for xen-devel@lists.xenproject.org; Thu, 26 Jan 2017 22:08:51 +0000 In-Reply-To: List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Errors-To: xen-devel-bounces@lists.xen.org Sender: "Xen-devel" To: Meng Xu Cc: George Dunlap , "xen-devel@lists.xenproject.org" , Anshul Makkar List-Id: xen-devel@lists.xenproject.org --===============5532185191276083715== Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="=-6wD4zZX2XcDSp1ullecA" --=-6wD4zZX2XcDSp1ullecA Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Thu, 2017-01-26 at 13:59 -0500, Meng Xu wrote: > Hi Dario, >=20 Hi, > On Thu, Jan 26, 2017 at 11:52 AM, Dario Faggioli > wrote: > > > > =C2=A0Runqueue 0: > > =C2=A0CPU[00] runq=3D0, sibling=3D00000000,00000003, core=3D00000000,00= 0000ff > > =C2=A0=C2=A0=C2=A0=C2=A0run: [0.15] flags=3D2 cpu=3D0 credit=3D5804742 = [w=3D256] load=3D3655 > > (~1%) > > =C2=A0CPU[01] runq=3D0, sibling=3D00000000,00000003, core=3D00000000,00= 0000ff > > =C2=A0CPU[02] runq=3D0, sibling=3D00000000,0000000c, core=3D00000000,00= 0000ff > > =C2=A0=C2=A0=C2=A0=C2=A0run: [0.3] flags=3D2 cpu=3D2 credit=3D6674856 [= w=3D256] load=3D262144 > > (~100%) > > =C2=A0CPU[03] runq=3D0, sibling=3D00000000,0000000c, core=3D00000000,00= 0000ff > > =C2=A0RUNQ: >=20 > What is the difference between RUNQ and Runqueue 0 in the message? >=20 Right. So, this is more comprehensive output: (XEN) [ 2797.156864] Cpupool 0: (XEN) [ 2797.156866] Cpus: 0-5,10-15 (XEN) [ 2797.156868] Scheduler: SMP Credit Scheduler rev2 (credit2) (XEN) [ 2797.156871] Active queues: 2 (XEN) [ 2797.156873]=C2=A0=C2=A0=C2=A0=C2=A0default-weight=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=3D 256 (XEN) [ 2797.156876] Runqueue 0: (XEN) [ 2797.156878]=C2=A0=C2=A0=C2=A0=C2=A0ncpus=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 6 (XEN) [ 2797.156879]=C2=A0=C2=A0=C2=A0=C2=A0cpus=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 0-5 (XEN) [ 2797.156881]=C2=A0=C2=A0=C2=A0=C2=A0max_weight=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 256 (XEN) [ 2797.156882]=C2=A0=C2=A0=C2=A0=C2=A0instload=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 5 (XEN) [ 2797.156884]=C2=A0=C2=A0=C2=A0=C2=A0aveload=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 1052984 (~401%) (XEN) [ 2797.156887]=C2=A0=C2=A0=C2=A0=C2=A0idlers: 00000000,0000002a (XEN) [ 2797.156889]=C2=A0=C2=A0=C2=A0=C2=A0tickled: 00000000,00000000 (XEN) [ 2797.156891]=C2=A0=C2=A0=C2=A0=C2=A0fully idle cores: 00000000,0000= 0000 (XEN) [ 2797.156894] Runqueue 1: (XEN) [ 2797.156896]=C2=A0=C2=A0=C2=A0=C2=A0ncpus=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 6 (XEN) [ 2797.156897]=C2=A0=C2=A0=C2=A0=C2=A0cpus=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 10-15 (XEN) [ 2797.156899]=C2=A0=C2=A0=C2=A0=C2=A0max_weight=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 256 (XEN) [ 2797.156900]=C2=A0=C2=A0=C2=A0=C2=A0instload=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 4 (XEN) [ 2797.156902]=C2=A0=C2=A0=C2=A0=C2=A0aveload=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=3D 1061305 (~404%) (XEN) [ 2797.156904]=C2=A0=C2=A0=C2=A0=C2=A0idlers: 00000000,0000e800 (XEN) [ 2797.156906]=C2=A0=C2=A0=C2=A0=C2=A0tickled: 00000000,00000000 (XEN) [ 2797.156908]=C2=A0=C2=A0=C2=A0=C2=A0fully idle cores: 00000000,0000= c000 (XEN) [ 2797.156910] Domain info: (XEN) [ 2797.156912] Domain: 0 w 256 v 16 (XEN) [ 2797.156914] 1: [0.0] flags=3D2 cpu=3D4 credit=3D-476120314 [w= =3D256] load=3D85800 (~32%) (XEN) [ 2797.156919] 2: [0.1] flags=3D0 cpu=3D2 credit=3D5630728 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.156923] 3: [0.2] flags=3D0 cpu=3D2 credit=3D4719251 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.156928] 4: [0.3] flags=3D2 cpu=3D2 credit=3D5648202 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.156933] 5: [0.4] flags=3D2 cpu=3D12 credit=3D2735243 [w= =3D256] load=3D262144 (~100%) (XEN) [ 2797.156939] 6: [0.5] flags=3D2 cpu=3D12 credit=3D2721770 [w= =3D256] load=3D262144 (~100%) (XEN) [ 2797.156945] 7: [0.6] flags=3D0 cpu=3D12 credit=3D2150753 [w= =3D256] load=3D262144 (~100%) (XEN) [ 2797.156950] 8: [0.7] flags=3D0 cpu=3D14 credit=3D10424341 [w= =3D256] load=3D2836 (~1%) (XEN) [ 2797.156986] 9: [0.8] flags=3D0 cpu=3D4 credit=3D10500000 [w= =3D256] load=3D14 (~0%) (XEN) [ 2797.156991] 10: [0.9] flags=3D0 cpu=3D14 credit=3D10500000 [w= =3D256] load=3D12 (~0%) (XEN) [ 2797.156995] 11: [0.10] flags=3D0 cpu=3D5 credit=3D9204778 [w= =3D256] load=3D7692 (~2%) (XEN) [ 2797.156999] 12: [0.11] flags=3D0 cpu=3D1 credit=3D10501097 [w= =3D256] load=3D2791 (~1%) (XEN) [ 2797.157004] 13: [0.12] flags=3D0 cpu=3D4 credit=3D10500000 [w= =3D256] load=3D28 (~0%) (XEN) [ 2797.157008] 14: [0.13] flags=3D0 cpu=3D11 credit=3D10500000 [w= =3D256] load=3D19 (~0%) (XEN) [ 2797.157013] 15: [0.14] flags=3D0 cpu=3D14 credit=3D10500000 [w= =3D256] load=3D388 (~0%) (XEN) [ 2797.157017] 16: [0.15] flags=3D0 cpu=3D3 credit=3D9832716 [w= =3D256] load=3D7326 (~2%) (XEN) [ 2797.157022] Domain: 1 w 256 v 2 (XEN) [ 2797.157024] 17: [1.0] flags=3D2 cpu=3D10 credit=3D-1085114190 = [w=3D256] load=3D261922 (~99%) (XEN) [ 2797.157029] 18: [1.1] flags=3D0 cpu=3D14 credit=3D10500000 [w= =3D256] load=3D0 (~0%) (XEN) [ 2797.157033] Domain: 2 w 256 v 2 (XEN) [ 2797.157035] 19: [2.0] flags=3D2 cpu=3D0 credit=3D-593239186 [w= =3D256] load=3D47389 (~18%) (XEN) [ 2797.157040] 20: [2.1] flags=3D0 cpu=3D11 credit=3D10500000 [w= =3D256] load=3D0 (~0%) (XEN) [ 2797.157044] Runqueue 0: (XEN) [ 2797.157047] CPU[00] runq=3D0, sibling=3D00000000,00000003, core=3D= 00000000,000000ff (XEN) [ 2797.157050] run: [2.0] flags=3D2 cpu=3D0 credit=3D-593239186 [w= =3D256] load=3D47389 (~18%) (XEN) [ 2797.157055] CPU[01] runq=3D0, sibling=3D00000000,00000003, core=3D= 00000000,000000ff (XEN) [ 2797.157058] CPU[02] runq=3D0, sibling=3D00000000,0000000c, core=3D= 00000000,000000ff (XEN) [ 2797.157061] run: [0.3] flags=3D2 cpu=3D2 credit=3D5648202 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.157066] CPU[03] runq=3D0, sibling=3D00000000,0000000c, core=3D= 00000000,000000ff (XEN) [ 2797.157069] CPU[04] runq=3D0, sibling=3D00000000,00000030, core=3D= 00000000,000000ff (XEN) [ 2797.157072] run: [0.0] flags=3D2 cpu=3D4 credit=3D-476120314 [w= =3D256] load=3D85800 (~32%) (XEN) [ 2797.157077] CPU[05] runq=3D0, sibling=3D00000000,00000030, core=3D= 00000000,000000ff (XEN) [ 2797.157080] RUNQ: (XEN) [ 2797.157081] 0: [0.1] flags=3D0 cpu=3D2 credit=3D5630728 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.157086] 1: [0.2] flags=3D0 cpu=3D2 credit=3D4719251 [w=3D= 256] load=3D262144 (~100%) (XEN) [ 2797.157090] Runqueue 1: (XEN) [ 2797.157093] CPU[10] runq=3D1, sibling=3D00000000,00000c00, core=3D= 00000000,0000ff00 (XEN) [ 2797.157096] run: [1.0] flags=3D2 cpu=3D10 credit=3D-1085114190 = [w=3D256] load=3D261922 (~99%) (XEN) [ 2797.157101] CPU[11] runq=3D1, sibling=3D00000000,00000c00, core=3D= 00000000,0000ff00 (XEN) [ 2797.157104] CPU[12] runq=3D1, sibling=3D00000000,00003000, core=3D= 00000000,0000ff00 (XEN) [ 2797.157108] run: [0.5] flags=3D2 cpu=3D12 credit=3D2715377 [w= =3D256] load=3D262144 (~100%) (XEN) [ 2797.157113] CPU[13] runq=3D1, sibling=3D00000000,00003000, core=3D= 00000000,0000ff00 (XEN) [ 2797.157118] CPU[14] runq=3D1, sibling=3D00000000,0000c000, core=3D= 00000000,0000ff00 (XEN) [ 2797.157121] CPU[15] runq=3D1, sibling=3D00000000,0000c000, core=3D= 00000000,0000ff00 (XEN) [ 2797.157125] RUNQ: (XEN) [ 2797.157126] 0: [0.6] flags=3D0 cpu=3D12 credit=3D2150753 [w= =3D256] load=3D262144 (~100%) (XEN) [ 2797.157131] 1: [0.4] flags=3D0 cpu=3D12 credit=3D1732714 [w= =3D256] load=3D262144 (~100%) "Runqueue 0" tells that what follow is information about the pCPUs and the vCPUs of that runqueue (it's the same label used above for, showing more general runqueue information. "RUNQ:" tells that what follows is the content of the runqueue, i.e., the vCPUs which are runnable but not running (the one that were running have been printed already, next to the pCPU they're running on), asn are waiting for their turn in this runqueue. Any better? > > diff --git a/xen/common/sched_rt.c b/xen/common/sched_rt.c > > index 24b4b22..f2d979c 100644 > > --- a/xen/common/sched_rt.c > > +++ b/xen/common/sched_rt.c > >=20 > > +=C2=A0=C2=A0=C2=A0=C2=A0/* current VCPU (nothing to say if that's the = idle vcpu). */ > > +=C2=A0=C2=A0=C2=A0=C2=A0svc =3D rt_vcpu(curr_on_cpu(cpu)); > > +=C2=A0=C2=A0=C2=A0=C2=A0if ( svc && !is_idle_vcpu(svc->vcpu) ) > > +=C2=A0=C2=A0=C2=A0=C2=A0{ > > +=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0rt_dump_vcpu(ops, svc)= ; > > +=C2=A0=C2=A0=C2=A0=C2=A0} >=20 > Maybe it is better to print the CPU number if the CPU is running an > idle VCPU. > The printk info could be: > =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0printk("CPU[%02d]: = idle\n", cpu); >=20 This is the output for RTDS, with this patch applied, as it is, with one idle and one busy pCPU: (XEN) [ 399.222117] Scheduler: SMP RTDS Scheduler (rtds) (XEN) [ 399.222120] Global RunQueue info: (XEN) [ 399.222122] Global DepletedQueue info: (XEN) [ 399.222125] Global Replenishment Events info: (XEN) [ 399.222132] [ 1.1 ] cpu 9, (10000000, 4000000), cur_b=3D4000000= cur_d=3D399230000000 last_start=3D399220062444 (XEN) [ 399.222136] onQ=3D0 runnable=3D1 flags=3D2 effective h= ard_affinity=3D8-9 (XEN) [ 399.222139] Domain info: (XEN) [ 399.222141] domain: 1 (XEN) [ 399.222147] [ 1.0 ] cpu 8, (10000000, 4000000), cur_b=3D3973291= cur_d=3D399230000000 last_start=3D399220130217 (XEN) [ 399.222151] onQ=3D0 runnable=3D0 flags=3D0 effective h= ard_affinity=3D8-9 (XEN) [ 399.222157] [ 1.1 ] cpu 9, (10000000, 4000000), cur_b=3D4000000= cur_d=3D399230000000 last_start=3D399220062444 (XEN) [ 399.222161] onQ=3D0 runnable=3D1 flags=3D2 effective h= ard_affinity=3D8-9 (XEN) [ 399.222164] CPUs info: (XEN) [ 399.222167] CPU[08] (XEN) [ 399.222169] CPU[09] (XEN) [ 399.222175] [ 1.1 ] cpu 9, (10000000, 4000000), cur_b=3D4000000= cur_d=3D399230000000 last_start=3D399220062444 (XEN) [ 399.222179] onQ=3D0 runnable=3D1 flags=3D2 effective h= ard_affinity=3D8-9 I don't see what adding "idle" buys us, wrt to just listing the CPU without printing anything particular. And, on a big and mostly idle system, it will be printed a lot of times (next to each idle pCPU). They're running nothing, so they're quite obviously idle. It looks this simple to me IMO. TBH, what I don't especially like in the output above is, within the vCPU info being printed: =C2=A0- the spaces inside '[' ']'; =C2=A0- the big numbers; =C2=A0- the fact that last_start is rather useless (it's more tracing info =C2=A0 =C2=A0than debug dump info, IMO); =C2=A0- the fact that the various queues info and CPUs info are not=C2=A0 =C2=A0 =C2=A0displaed closer, and they even have "Domain info:" in between = them =C2=A0 =C2=A0(which is because of schedule.c, not sched_rt.c, I know); =C2=A0- the word "info" after "Global RunQueue", "Global DepletedQueue",=C2= =A0 =C2=A0 =C2=A0"Global Replenishment Events"; =C2=A0- the word "Global", in the names above; =C2=A0- the onQ and runnable flags being printed, which I don't is really =C2=A0 =C2=A0necessary or useful; =C2=A0- the lack of scheduler wide information (e.g., the tickled mask, the =C2=A0 =C2=A0next timeout of the replenishment timer, etc); But this is material for another patch. :-) Going back to printing "idle" or not, also remember that this is debug output, meant at being mostly useful for developers, or with help from developers. And developers can easily check in the code what having just the CPU ID printed means (in case it's not obvious, which I think it is, or they don't remember). That being said, it's not that I can't live with the added "idle" indication. But I like it less and would prefer not to add it. Thanks and Regards, Dario --=C2=A0 <> (Raistlin Majere) ----------------------------------------------------------------- Dario Faggioli, Ph.D, http://about.me/dario.faggioli Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK) --=-6wD4zZX2XcDSp1ullecA Content-Type: application/pgp-signature; name="signature.asc" Content-Description: This is a digitally signed message part Content-Transfer-Encoding: 7bit -----BEGIN PGP SIGNATURE----- Version: GnuPG v2 iQIcBAABCAAGBQJYinNpAAoJEBZCeImluHPuTCQQAIXtC7i78VAC+5gED9A9nBqB VKcaZICKKnR0OX29jtl4AnxjWUuDtK3GuIJKnhXkEn/N6THMSHFzzOfzYYiGCw1S V/pC2tOcs/CDX0JNiPi8tAWozKyuH9AfIXfBbM6GU6N0rl3RTGdFcbYgvhYKr1qM UemeldgKIv19kC4u1sow1YbNMWqHN9Vn1xIMEleENDfp28lAMq5H7qz/+OfsnyaK 50sqqlmhx57WHxvLmeDIf0pFa5hGWV7tSQ1zD/ic0eQGW2MxLNzgDN0pWfLMylXX SbCsZtbOzguGSrLpRjV4tiOgYlf3deaJLwJ9pdEEuEITFXryErYSuwRGsfNmH54p mkwSoWRs1KXEeaz1suXzcGW3fK0XdEIIyZytn6boslqDlfLeTSiovbDKYtuqT8mA Ks5TAJyYYCsifq51oAe9UySefLjwfsjYVivXCYTUWg8PoQZ0PQcYid1IS6EZjYDE oFzGrr9q8RJFVCjHR+Y0XEPigxRF5fQoqhJ0doTOEyX/WyQmuT3R7vIw01FzpScV jv0vYWOXZlFShfxassr2BCa0f+qK1yo+RAfgU1G9jwFthbMCtSt+cSOiVWjstvxi Z+8Q1V+U43xGzuVP4ks4ZlWGvTZaLe7+cSauq37688aLp2glL5rgDz4uK1Pa3U4c G7H5JRrjK1BTZ0jawOQc =b/pp -----END PGP SIGNATURE----- --=-6wD4zZX2XcDSp1ullecA-- --===============5532185191276083715== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: base64 Content-Disposition: inline X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX18KWGVuLWRldmVs IG1haWxpbmcgbGlzdApYZW4tZGV2ZWxAbGlzdHMueGVuLm9yZwpodHRwczovL2xpc3RzLnhlbi5v cmcveGVuLWRldmVsCg== --===============5532185191276083715==--