Re: Kernelshark v2 all-black plots area

[Dario Faggioli <dfaggioli@suse.com>]

[-- Attachment #1: Type: text/plain, Size: 5141 bytes --]

On Wed, 2021-02-10 at 13:21 +0200, Yordan Karadzhov (VMware) wrote:
> On 9.02.21 г. 18:13 ч., Dario Faggioli wrote:
> > Indeed it does, thanks a lot again.
> > 
> > Now, if I try "KVM Combo Plot":
> > - I still see super weird results if I use the KVM clock from last
> >    patch in Tzvetomir series (but I guess I'll report it there).
> 
> Can you share a screenshot of the one that looks weird. And please do
> some deeper zooming because it is very hard to judge about the
> quality 
> of the sync from such a broad time window.
> 
Sure, let me try.

So, while tracing, I see this, so I think I'm in fact using the KVM
clock (ignore the "(null)" thing, we're dealing with it in another
thread):

  Negotiated kvm time sync protocol with guest (null)

When start KernelShark 2 on trace.dat (the host trace), I see this on
the terminal:

 ./kernel-shark-v2.beta.git/bin/kernelshark trace.dat 
loading plugin "sched_events" from /home/dario/Sources/tracing/kernel-shark-v2.beta.git/lib/plugin-sched_events.so
loading plugin "missed_events" from /home/dario/Sources/tracing/kernel-shark-v2.beta.git/lib/plugin-missed_events.so
loading plugin "event_field_plot" from /home/dario/Sources/tracing/kernel-shark-v2.beta.git/lib/plugin-event_field_plot.so
loading plugin "latency_plot" from /home/dario/Sources/tracing/kernel-shark-v2.beta.git/lib/plugin-latency_plot.so
loading plugin "kvm_combo" from /home/dario/Sources/tracing/kernel-shark-v2.beta.git/lib/plugin-kvm_combo.so
--> KVM combos init menu
--> latency_plot init menu
plugin_latency_add_menu 0x100aea0
--> event_field init menu
plugin_efp_add_menu 0xf51510
--> sched init menu
Loading  "trace.dat"
version = 6

And this is how the GUI looks:

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host.png

Then, I append the trace-(null).dat file (the guest trace). I do see
this on the terminal:

overriding event (1) ftrace:function with new print handler
overriding event (10) ftrace:funcgraph_exit with new print handler
overriding event (11) ftrace:funcgraph_entry with new print handler
<-- sched close 0
<-- missed_events close 0
<-- KVM combos close 0
--> KVM combos init 0 
--> missed_events init 0
--> sched init 0
--> KVM combos init 1 
plugin "kvm_combo" failed to initialize on stream /home/dario/Sources/tracing/trace-(null).dat
--> missed_events init 1
--> sched init 1

And the GUI looks like this:

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host_guest.png

The guest has 1 vCPU and is pinned to host pCPU 1. There are two `yes`
task running inside it. On the host, there are two `yes` task too, also
pinned to vCPU 1, so that there's some resource contention.

This is the very same configuration of the other experiment, for which
I showed the screenshot in the other email, when using PTP.

There, things were kind of ok. Here, it seems that the host events are
gone, but if I zoom a lot at the very beginning of the trace, I do see
them again:

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host_guest-zoom.png

Point is that the traces are not in sync. Actually, it looks to me that
the timestamps of the guest traces are the most weird part, as they
look rather big, not really consistent among each other and some are
even negative!

IAC, the events from the two traces are shown as two completely
disjoint sets:

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host_guest-events.png
http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host_guest-events-zoom.png.png

If I try a KVM-Combo, this is how it looks (not really surprisingly):

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-host_guest-combo.png

Note that if I just open the guest trace in a new session, it looks
fine:

http://xenbits.xen.org/people/dariof/ks2-debug/kernelshark-v2-guest.png

I'm uploading the two trace files here, in case it could be useful:

http://xenbits.xen.org/people/dariof/ks2-debug/

> > - If I use PTP, that kind of works.
> > 
> > If I trace a `sleep 1` on the host, the result is like this:
> > 
> > http://xenbits.xen.org/people/dariof/kernelshark-v2-ptp.png
> 
> Is this a PTP synchronization?
> 
It is, yes.

> > So, there is ~ 1 sec of data from the guest, coming from trace-cmd
> > agent. The host, however, went on and traced a little bit longer,
> > even
> > after closing the connection. It's not too terrible, I'm just
> > curious
> > whether this is known or it's something weird and it's only me
> > seeing
> > it.
> 
> I think this is normal.
> 
Right.

> But anyway Ceco (Tzvetomir) is the right person to answer questions 
> about the timestamp synchronization. Unfortunately he is on vacation 
> till the end of the week.
> 
Sure, no problem!

Thanks and Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]