From mboxrd@z Thu Jan 1 00:00:00 1970 From: Dario Faggioli Subject: Re: [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing Date: Wed, 7 Jun 2017 17:45:53 +0200 Message-ID: <1496850353.9462.3.camel@citrix.com> References: <149633614204.12814.14390287626133023934.stgit@Solace.fritz.box> <149633843555.12814.16573412358602741145.stgit@Solace.fritz.box> <5938323D02000078001607B7@prv-mh.provo.novell.com> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="===============5669333669680818481==" Return-path: Received: from mail6.bemta5.messagelabs.com ([195.245.231.135]) by lists.xenproject.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dIdBW-0007gq-Nv for xen-devel@lists.xenproject.org; Wed, 07 Jun 2017 15:47:50 +0000 In-Reply-To: <5938323D02000078001607B7@prv-mh.provo.novell.com> List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Errors-To: xen-devel-bounces@lists.xen.org Sender: "Xen-devel" To: Jan Beulich Cc: George Dunlap , Andrew Cooper , Wei Liu , Ian Jackson , xen-devel@lists.xenproject.org List-Id: xen-devel@lists.xenproject.org --===============5669333669680818481== Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="=-Rheqz58jx6akUKDGTtTi" --=-Rheqz58jx6akUKDGTtTi Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Wed, 2017-06-07 at 09:05 -0600, Jan Beulich wrote: > > > > On 01.06.17 at 19:33, wrote: > >=20 > > More specifically: > > =C2=A0- the handling of the TRC_HW_IRQ_HANDLED is fixed, both in > > =C2=A0=C2=A0=C2=A0xentrace_format and in xenalyze; > > =C2=A0- simple events for recording when we enter and exit the > > =C2=A0=C2=A0=C2=A0do_IRQ function, as well as when we deal with a guest > > =C2=A0=C2=A0=C2=A0IRQ, are added; >=20 > On x86. What about ARM? >=20 We don't have tracing at all on ARM. I guess I can mention this in the commit message (and, perhaps, even add an 'x86' tag to the subject). > > =C2=A0- tracing of IRQs handled with direct vectors is also > > =C2=A0=C2=A0=C2=A0added. > >=20 > > With all the above, a trace will now look like this (using > > xenalyze): > >=20 > > =C2=A00.001299072 .x- d32768v5 irq_enter, irq 80000000 > > =C2=A00.001299072 .x- d32768v5 irq_direct, vec fa, handler =3D > > 0xffff82d08026d7e4 > > =C2=A00.001300014 .x- d32768v5 raise_softirq nr 0 > > =C2=A00.001300487 .x- d32768v5 irq_exit irq 80000000, in_irq =3D 0 >=20 > The IRQ number looks bogus here, and I'm not convinced giving > a bogus example in a commit message is a good idea. I realize > this is presumably a result of vector_irq[] being initialized to > INT_MIN, but I would say the trace points would then better be > moved so that no bogus data is being recorded. >=20 Ok, I'll have a look at how to achieve that. > > @@ -884,9 +919,13 @@ void do_IRQ(struct cpu_user_regs *regs) > > =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=A0desc->rl_quantum_start =3D now; > > =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=C2=A0=C2=A0=C2=A0tsc_in =3D tb_init_don= e ? get_cycles() : 0; > > +=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0if ( unlikely(tb_init_= done) ) > > +=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=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0__trace_var(TRC_HW_IRQ_GUEST, 0, sizeof(irq), &irq); > > +=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0tsc_in =3D get_cycles(); > > +=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=C2=A0=C2=A0__do_IRQ_guest(ir= q); > > -=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TRACE_3D(TRC_HW_IRQ_HA= NDLED, irq, tsc_in, get_cycles()); > > +=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0trace_irq_handled(irq,= get_cycles() - tsc_in); > > =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0goto out_no_end; > > =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0} >=20 > Before this change, the get_cycles() invocation was after > the tb_init_done check. Now you move it ahead of it (as > the function arguments are evaluated before executing the > function body) - are you sure all compiler versions will suitably > re-order this? >=20 > Additionally I'm afraid this will trigger compiler warnings on at > least some compiler versions, as tsc_in is now possibly > uninitialized (and there's no clear way to disprove this for the > compiler, again because function arguments are being > evaluated before the function body is reached). >=20 I understand and (now that I see it) agree with your remark on when get_cycles() is called. I'll reorganize things so that the patched behavior matches the existing one. OTOH, I'm not sure I see the "potentially uninitialized" issue for tsc_in, but since I'm reworking the code, I'll keep that in mind too. > As to get_cycles() itself - is the relatively imprecise time > stamp it produces really good enough for tracing? I notice > that there are only very few other users of that function. >=20 Yes, that's also something I was wondering. It's what is being used currently, so I thought it was like that for a reason, and that it wasn't this patch job to change that. But if it's judged to be fine to turn this into NOW() (done either here, or in a dedicated patch)., I'm all for it. > > @@ -922,6 +962,7 @@ void do_IRQ(struct cpu_user_regs *regs) > > =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0spin_unlock(&desc->lock); > > =C2=A0 out_no_unlock: > > =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0irq_exit(); > > +=C2=A0=C2=A0=C2=A0=C2=A0TRACE_3D(TRC_HW_IRQ_EXIT, irq, desc =3D=3D NUL= L ? -1 : desc- > > >status, in_irq()); >=20 > The ordering of irq_{enter,exit}() and TRACE_{1,3}D() may be > preferable from a trace quality pov, but as far as the system is > concerned you're adding code which runs in interrupt context > without being aware of that. This may be a latent issue. >=20 Sorry, I don't understand your concern(s). What is it that I am not aware of, and what is it that could be a latent issue? About the position of those tracepoints: the nice thing about IRQ_EXIT following irq_exit() is that I can record the result of in_irq(), which will tell whether or not we're dealing with a nested interrupt. I don't do the same for IRQ_ENTER, but, not that I think about it, I guess I could. However, if what you're saying is that they need to stay within the irq_enter()-irq_exit() section, I can certainly make that happen. The trace needs to be interpreted knowing where the tracepoints are anyway (and that's true for each and every event already), so no big deal, really. Thanks and Regards, Dario --=20 <> (Raistlin Majere) ----------------------------------------------------------------- Dario Faggioli, Ph.D, http://about.me/dario.faggioli Senior Software Engineer, Citrix Systems R&D Ltd., Cambridge (UK) --=-Rheqz58jx6akUKDGTtTi 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 iQIcBAABCAAGBQJZOB+yAAoJEBZCeImluHPuJBwQAKMaqxNB4SOJvigFurZX6XYp 95LQJBCB19wwUkjNSyv4hwvg4/9adEtFx4pP7ezIfJN/jtgc2etFL5jVzFFy+miW XDLC3EPgxEGkRaqqJfXVG4mPRRSCMMmuuh03AQdrWFoSV7EooC2CeNPu5dzBSa90 DbRUBSOvEM2VyOo6pJpllYM3PmA8y1bdH3UbOWA+8yGVnw/AYi8JTTa0j+PiW2D5 YyNgjnnFu/2j+nUXGYV4mZoc4qor5wdJ2PkcGce6GqtV7RolXqd7RDuCuufGpO0x EolsDztXzyLqguNaVE9kgo1FejVUJUwxiI1f2RsFUEM5Dkywaz4W4CwWuu7Kie2U BiiZ5NNPomcXmphpzjZm6UYp2XxklaWWHhS81ve+gcEeovjbJi2ozKYUHJp68zFS zoxjCDixi5D1fAieuCOtjiTAS4RzPdxbp37+z7RpMyhvy10Tym8/dpnsR1bcA6CU lH/kKMWZbpr9g8bkdpYpu0TLMBBY11Jl9lSaR2orKaXKoHZqpqUshnSm51n+DTfw bOxjFaBtv9B32b9wEKa38stXx8n57yOLuNvzxP47yyfL/n0OmYLTgkLjl948jTqX Tr7waYjJcQ7gqd6E6l6WceUHZabTDbyotGB3WvAuFguivsNHI/n6VitBqIFT++6L aM/joD9JhFl9LuSn2g8t =TR6H -----END PGP SIGNATURE----- --=-Rheqz58jx6akUKDGTtTi-- --===============5669333669680818481== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: base64 Content-Disposition: inline X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX18KWGVuLWRldmVs IG1haWxpbmcgbGlzdApYZW4tZGV2ZWxAbGlzdHMueGVuLm9yZwpodHRwczovL2xpc3RzLnhlbi5v cmcveGVuLWRldmVsCg== --===============5669333669680818481==--