Re: Instructions for clock sync for tracing host/guest

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

Hi Joel,

On Fri, Apr 23, 2021 at 1:50 AM Joel Fernandes <joelaf@google.com> wrote:
>
> Looks like my trace.dat files bounced from goodmis.org so I uploaded them here:
> https://drive.google.com/file/d/16wGsVo4PJ0kYQGAy195dfBW0RHSWVkx0/view?usp=sharing
>
> ---------- Forwarded message ---------
> From: Joel Fernandes <joelaf@google.com>
> Date: Thu, Apr 22, 2021 at 6:46 PM
> Subject: Re: Instructions for clock sync for tracing host/guest
> To: Steven Rostedt <rostedt@goodmis.org>, Yordan Karadzhov (VMware)
> <y.karadz@gmail.com>
> Cc: Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
>
>
> On Thu, Apr 22, 2021 at 5:12 PM Joel Fernandes <joelaf@google.com> wrote:
> >
> > On Thu, Apr 22, 2021 at 4:03 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Thu, 22 Apr 2021 15:49:21 -0400
> > > Joel Fernandes <joelaf@google.com> wrote:
> > >
> > > > On Thu, Apr 22, 2021 at 3:48 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> > > > >
> > > > > On Thu, 22 Apr 2021 15:43:37 -0400
> > > > > Joel Fernandes <joelaf@google.com> wrote:
> > > > >
> > > > > > >  # trace-cmd record -e irq -e sched -e kvm -A test@32:823 -e sched
> > > > > >
> > > > > > OMG, that worked, thank you Steve and Tzvetomir !!!!!
> > > > >
> > > > > Technically, you can probably leave off "-e irq", but I do find it rather
> > > > > useful. But then, I add "-e irq" to the guest as well. It lets me see how
> > > > > interrupts transpire from the host to the guest.
> > > >
> > > > Got it thanks for the tip. Will report back any issues I see.
> > >
> > > And you know you can pull this up into KernelShark as well, right?
> > >
> > > Checkout the development version from Yordan's repository:
> > >
> > >
> > >  $ git clone https://github.com/yordan-karadzhov/kernel-shark.git
> > >  $ cd kernel-shark
> > >  $ git checkout origin/yordan_devel
> > >  $ cmake .
> > >  $ make
> > >  $ sudo make install
> > >
> > > Then run kernelshark with:
> > >
> > >  $ kernelshark trace-host.dat -a trace-guest.dat
> > >
> > > (obviously, using the actual names of the trace.dat files for the host and
> > > the guest)
> > >
> > > Then you can select: Plots -> KVM Combo Plots
> > >
> > > Then select the "all" box, and then apply. Then you get something like this:
> > >
> > >   http://rostedt.org/private/ks-host-guest.png
> > >
> > > Where you see how the tasks mapping to the host and guest are aligned.
> > >
> > > That is, if everything works fine.
> >
> > Yes, I sort of knew KernelShark had this support, but so glad you sent
> > me more details on how to do it, I'll try it out. I am also wondering
> > how the bars of the vCPUs will look like because you can have vCPU
> > threads migrated to different physical CPUs. I will go try it out and
> > see what comes up :-)
>
> Hi all, Just wanted to report my progress today:
>
> When I try to open the guest+host trace with the yordan_devel branch and command
> kernelshark ~/vm-host-trace/trace.dat -a ~/vm-host-trace/trace-test.dat
>
> I get the following in the console: https://pastebin.com/raw/EmbsyuB8
>
> And the GUI looks like the attached picture, I don't see any mention
> of KVM like Steve sees in
> http://rostedt.org/private/ks-host-guest.png . What am I missing?
>
> I also zipped and attached my trace files to this email. Could you
> take a look at them?

Looks like there is a gap in our implementation, affecting your use
case. We rely too much on the quemu guest information that we gather,
which is missing on your setup. As this information is not mandatory,
the implementation should not rely on it. What we need:
 - PID of the process, running the guest VM. In case of KVM, we use
this PID to get the KVM guest TSC clock parameters, needed for better
host and guest trace timestamps synchronization. Without this PID, KVM
cannot be used for timestamps synchronization. The logic should fail
back to a PTP-like algorithm, which is more generic, works in all
environments, but is less accurate than KVM logic.
 - PIDs of each thread, running a guest virtual CPU. This is not
required for the tracing, but for better trace visualisation in
KernelShark. It helps to map the host task to a vCPU and to visualise
them together.

Currently we collect that information from quemu, is there a way to
get it from crosvm ? If yes, a crosvm support can be implemented in
trace-cmd. But as I said, it is not mandatory to have it for the
trace, I can send you a patch next week addressing this gap in the
implementation.

Thanks for testing this code!

>
> My kernelshark HEAD commit is: 070d657 ("kernel-shark: Add KVMCombo
> plugin") . Let me know if I should be building some other commit sha.
>
> Adding Yordan to this email as well.
>
> Thanks a lot!
> -Joel



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

Hi Joel,

FYI, VMware gave everyone the day off today, so don't expect any real
responses till next week.

On Fri, 23 Apr 2021 04:37:40 -0400
Joel Fernandes <joelaf@google.com> wrote:

> Apologies for the top post as I'm on Gmail mobile and only half awake at
> 4.30am.  I should check but can we just scrape the crosvm PIDs from the
> host trace itself ? The vCPU threads are in scheduler events in the host
> trace. Of course that wouldn't work if we don't have events. Let me know if
> that works for you or if I should find another way.
> 
> By the way if sync is supposed to fall back to the ptp algo, why did it not
> fallback for me?

If both guest and host support an algo, it will use the one that has the
best synchronization (like KVM). If the guest says it supports KVM and the
host says it supports KVM, then it will use it. The question now remains,
did one of them lie? ;-)

> 
> Other thoughts:
> - it would be cool if trace cmd agent was run by the host directly on the
> guest. That might eliminate a step. I can try to see if that's possible
> with crosvm but it's not super high priority.

Not sure what you mean by that.

> 
> Yes thanks for sending me any patches and happy to try.

Feel free to send us patches too! ;-)

Anyway, see you next week.

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Joel Fernandes]

On Fri, Apr 23, 2021 at 7:33 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> Hi Joel,
>
> FYI, VMware gave everyone the day off today, so don't expect any real
> responses till next week.

Got it.

> On Fri, 23 Apr 2021 04:37:40 -0400
> Joel Fernandes <joelaf@google.com> wrote:
>
> > Apologies for the top post as I'm on Gmail mobile and only half awake at
> > 4.30am.  I should check but can we just scrape the crosvm PIDs from the
> > host trace itself ? The vCPU threads are in scheduler events in the host
> > trace. Of course that wouldn't work if we don't have events. Let me know if
> > that works for you or if I should find another way.
> >
> > By the way if sync is supposed to fall back to the ptp algo, why did it not
> > fallback for me?
>
> If both guest and host support an algo, it will use the one that has the
> best synchronization (like KVM). If the guest says it supports KVM and the
> host says it supports KVM, then it will use it. The question now remains,
> did one of them lie? ;-)

Good question, will try to debug and see what each said.

> > Other thoughts:
> > - it would be cool if trace cmd agent was run by the host directly on the
> > guest. That might eliminate a step. I can try to see if that's possible
> > with crosvm but it's not super high priority.
>
> Not sure what you mean by that.

I meant that currently, doing "trace-cmd agent" in the guest is an
extra step. I'd rather the "trace-cmd record" on the host spawn the
agent within the guest somehow, thus eliminating that extra step.

> > Yes thanks for sending me any patches and happy to try.
>
> Feel free to send us patches too! ;-)

Yes, certainly. My first attempt was to see if I could hit the ground
running with my VM problems, if trace-cmd was in sufficient shape.
Looks like trace-cmd is almost there and happy to help with the best
of my ability to write any patches.

> Anyway, see you next week.

You too, thanks,
-Joel

>
> -- Steve

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Fri, 23 Apr 2021 11:16:50 +0300
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> Currently we collect that information from quemu, is there a way to
> get it from crosvm ? If yes, a crosvm support can be implemented in
> trace-cmd. But as I said, it is not mandatory to have it for the
> trace, I can send you a patch next week addressing this gap in the
> implementation.

I think we should be able to get the above information during the KVM
timesync logic. The host can enable KVM events (specifically
kvm_entry), and that should give use the pids.

 # trace-cmd record -e kvm_entry ssh guest taskset -c 0 ls \; taskset -c 1 cat /etc/passwd
 # trace-cmd report
[..]
           <...>-129042 [004]1122452427093922: kvm_entry:            vcpu 0
           <...>-129043 [005]1122452427148178: kvm_entry:            vcpu 1
           <...>-129042 [004]1122452427150380: kvm_entry:            vcpu 0
           <...>-129043 [005]1122452427201498: kvm_entry:            vcpu 1

There, I see the guest vcpu 0 is controlled by the host thread with pid
129042 and vcpu 1 is controlled by host thread pid 129043.

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

On Sun, Apr 25, 2021 at 9:29 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 23 Apr 2021 11:16:50 +0300
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
>
> > Currently we collect that information from quemu, is there a way to
> > get it from crosvm ? If yes, a crosvm support can be implemented in
> > trace-cmd. But as I said, it is not mandatory to have it for the
> > trace, I can send you a patch next week addressing this gap in the
> > implementation.
>
> I think we should be able to get the above information during the KVM
> timesync logic. The host can enable KVM events (specifically
> kvm_entry), and that should give use the pids.
>
>  # trace-cmd record -e kvm_entry ssh guest taskset -c 0 ls \; taskset -c 1 cat /etc/passwd
>  # trace-cmd report
> [..]
>            <...>-129042 [004]1122452427093922: kvm_entry:            vcpu 0
>            <...>-129043 [005]1122452427148178: kvm_entry:            vcpu 1
>            <...>-129042 [004]1122452427150380: kvm_entry:            vcpu 0
>            <...>-129043 [005]1122452427201498: kvm_entry:            vcpu 1
>
> There, I see the guest vcpu 0 is controlled by the host thread with pid
> 129042 and vcpu 1 is controlled by host thread pid 129043.

It works only in case of one VM, if there are more than one - cannot
map kvm_entry event to specific VM.

>
> -- Steve



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

On Fri, Apr 23, 2021 at 11:37 AM Joel Fernandes <joelaf@google.com> wrote:
>
> Apologies for the top post as I'm on Gmail mobile and only half awake at 4.30am.  I should check but can we just scrape the crosvm PIDs from the host trace itself ? The vCPU threads are in scheduler events in the host trace. Of course that wouldn't work if we don't have events. Let me know if that works for you or if I should find another way.
>
> By the way if sync is supposed to fall back to the ptp algo, why did it not fallback for me?

Because of a bug in the code. It assumes if KVM is detected, then qemu
is used to run the VMs.

>
> Other thoughts:
> - it would be cool if trace cmd agent was run by the host directly on the guest. That might eliminate a step. I can try to see if that's possible with crosvm but it's not super high priority.

That will require to have some already established communication
channel between host and guest. We can use ssh for example, but the
user must set up in advance ssh server and pass credentials to
tracec-cmd on the host.

>
> Yes thanks for sending me any patches and happy to try.

Just sent a patch that should fix the problem. Please, test it when
you have time. The PTP-like algorithm will be used for trace
timestamps synchronization, the best accuracy can be achieved using
mono_raw trace clock:
   host# trace-cmd record -e <host events> -C mono_raw -A test@32:823
-e <guest events>

Steven, may be mono_raw clock should be the default in this case, when
PTP is used for the synchronization ?

>
>
> On Fri, Apr 23, 2021, 4:17 AM Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
>>
>> Hi Joel,
>>
>> On Fri, Apr 23, 2021 at 1:50 AM Joel Fernandes <joelaf@google.com> wrote:
>> >
>> > Looks like my trace.dat files bounced from goodmis.org so I uploaded them here:
>> > https://drive.google.com/file/d/16wGsVo4PJ0kYQGAy195dfBW0RHSWVkx0/view?usp=sharing
>> >
>> > ---------- Forwarded message ---------
>> > From: Joel Fernandes <joelaf@google.com>
>> > Date: Thu, Apr 22, 2021 at 6:46 PM
>> > Subject: Re: Instructions for clock sync for tracing host/guest
>> > To: Steven Rostedt <rostedt@goodmis.org>, Yordan Karadzhov (VMware)
>> > <y.karadz@gmail.com>
>> > Cc: Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
>> >
>> >
>> > On Thu, Apr 22, 2021 at 5:12 PM Joel Fernandes <joelaf@google.com> wrote:
>> > >
>> > > On Thu, Apr 22, 2021 at 4:03 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>> > > >
>> > > > On Thu, 22 Apr 2021 15:49:21 -0400
>> > > > Joel Fernandes <joelaf@google.com> wrote:
>> > > >
>> > > > > On Thu, Apr 22, 2021 at 3:48 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>> > > > > >
>> > > > > > On Thu, 22 Apr 2021 15:43:37 -0400
>> > > > > > Joel Fernandes <joelaf@google.com> wrote:
>> > > > > >
>> > > > > > > >  # trace-cmd record -e irq -e sched -e kvm -A test@32:823 -e sched
>> > > > > > >
>> > > > > > > OMG, that worked, thank you Steve and Tzvetomir !!!!!
>> > > > > >
>> > > > > > Technically, you can probably leave off "-e irq", but I do find it rather
>> > > > > > useful. But then, I add "-e irq" to the guest as well. It lets me see how
>> > > > > > interrupts transpire from the host to the guest.
>> > > > >
>> > > > > Got it thanks for the tip. Will report back any issues I see.
>> > > >
>> > > > And you know you can pull this up into KernelShark as well, right?
>> > > >
>> > > > Checkout the development version from Yordan's repository:
>> > > >
>> > > >
>> > > >  $ git clone https://github.com/yordan-karadzhov/kernel-shark.git
>> > > >  $ cd kernel-shark
>> > > >  $ git checkout origin/yordan_devel
>> > > >  $ cmake .
>> > > >  $ make
>> > > >  $ sudo make install
>> > > >
>> > > > Then run kernelshark with:
>> > > >
>> > > >  $ kernelshark trace-host.dat -a trace-guest.dat
>> > > >
>> > > > (obviously, using the actual names of the trace.dat files for the host and
>> > > > the guest)
>> > > >
>> > > > Then you can select: Plots -> KVM Combo Plots
>> > > >
>> > > > Then select the "all" box, and then apply. Then you get something like this:
>> > > >
>> > > >   http://rostedt.org/private/ks-host-guest.png
>> > > >
>> > > > Where you see how the tasks mapping to the host and guest are aligned.
>> > > >
>> > > > That is, if everything works fine.
>> > >
>> > > Yes, I sort of knew KernelShark had this support, but so glad you sent
>> > > me more details on how to do it, I'll try it out. I am also wondering
>> > > how the bars of the vCPUs will look like because you can have vCPU
>> > > threads migrated to different physical CPUs. I will go try it out and
>> > > see what comes up :-)
>> >
>> > Hi all, Just wanted to report my progress today:
>> >
>> > When I try to open the guest+host trace with the yordan_devel branch and command
>> > kernelshark ~/vm-host-trace/trace.dat -a ~/vm-host-trace/trace-test.dat
>> >
>> > I get the following in the console: https://pastebin.com/raw/EmbsyuB8
>> >
>> > And the GUI looks like the attached picture, I don't see any mention
>> > of KVM like Steve sees in
>> > http://rostedt.org/private/ks-host-guest.png . What am I missing?
>> >
>> > I also zipped and attached my trace files to this email. Could you
>> > take a look at them?
>>
>> Looks like there is a gap in our implementation, affecting your use
>> case. We rely too much on the quemu guest information that we gather,
>> which is missing on your setup. As this information is not mandatory,
>> the implementation should not rely on it. What we need:
>>  - PID of the process, running the guest VM. In case of KVM, we use
>> this PID to get the KVM guest TSC clock parameters, needed for better
>> host and guest trace timestamps synchronization. Without this PID, KVM
>> cannot be used for timestamps synchronization. The logic should fail
>> back to a PTP-like algorithm, which is more generic, works in all
>> environments, but is less accurate than KVM logic.
>>  - PIDs of each thread, running a guest virtual CPU. This is not
>> required for the tracing, but for better trace visualisation in
>> KernelShark. It helps to map the host task to a vCPU and to visualise
>> them together.
>>
>> Currently we collect that information from quemu, is there a way to
>> get it from crosvm ? If yes, a crosvm support can be implemented in
>> trace-cmd. But as I said, it is not mandatory to have it for the
>> trace, I can send you a patch next week addressing this gap in the
>> implementation.
>>
>> Thanks for testing this code!
>>
>> >
>> > My kernelshark HEAD commit is: 070d657 ("kernel-shark: Add KVMCombo
>> > plugin") . Let me know if I should be building some other commit sha.
>> >
>> > Adding Yordan to this email as well.
>> >
>> > Thanks a lot!
>> > -Joel
>>
>>
>>
>> --
>> Tzvetomir (Ceco) Stoyanov
>> VMware Open Source Technology Center



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 13:58:18 +0300
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> On Fri, Apr 23, 2021 at 11:37 AM Joel Fernandes <joelaf@google.com> wrote:
> >
> > Apologies for the top post as I'm on Gmail mobile and only half awake at 4.30am.  I should check but can we just scrape the crosvm PIDs from the host trace itself ? The vCPU threads are in scheduler events in the host trace. Of course that wouldn't work if we don't have events. Let me know if that works for you or if I should find another way.
> >
> > By the way if sync is supposed to fall back to the ptp algo, why did it not fallback for me?  
> 
> Because of a bug in the code. It assumes if KVM is detected, then qemu
> is used to run the VMs.
> 

We need to find a way to do this without qemu. It's only the thread mapping
that is missing here, nothing else. And KVM sync should still work.

> >
> > Other thoughts:
> > - it would be cool if trace cmd agent was run by the host directly on the guest. That might eliminate a step. I can try to see if that's possible with crosvm but it's not super high priority.  
> 
> That will require to have some already established communication
> channel between host and guest. We can use ssh for example, but the
> user must set up in advance ssh server and pass credentials to
> tracec-cmd on the host.
> 
> >
> > Yes thanks for sending me any patches and happy to try.  
> 
> Just sent a patch that should fix the problem. Please, test it when
> you have time. The PTP-like algorithm will be used for trace
> timestamps synchronization, the best accuracy can be achieved using
> mono_raw trace clock:
>    host# trace-cmd record -e <host events> -C mono_raw -A test@32:823
> -e <guest events>
> 
> Steven, may be mono_raw clock should be the default in this case, when
> PTP is used for the synchronization ?

I think local is probably the safest.

> 
> >
> >
> > On Fri, Apr 23, 2021, 4:17 AM Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:  

And by the way, Tzvetomir, PLEASE crop the end of your email if you don't
have any more comments or at least add a signature in your last comment.
It is annoying to scroll through the rest of the email to find nothing else
was stated. This is a big pet peeve of many kernel developers.

-- Steve


> >>
> >> Hi Joel,
> >>
> >> On Fri, Apr 23, 2021 at 1:50 AM Joel Fernandes <joelaf@google.com> wrote:  
> >> >
> >> > Looks like my trace.dat files bounced from goodmis.org so I uploaded them here:
> >> > https://drive.google.com/file/d/16wGsVo4PJ0kYQGAy195dfBW0RHSWVkx0/view?usp=sharing
> >> >
> >> > ---------- Forwarded message ---------
> >> > From: Joel Fernandes <joelaf@google.com>
> >> > Date: Thu, Apr 22, 2021 at 6:46 PM
> >> > Subject: Re: Instructions for clock sync for tracing host/guest
> >> > To: Steven Rostedt <rostedt@goodmis.org>, Yordan Karadzhov (VMware)
> >> > <y.karadz@gmail.com>
> >> > Cc: Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
> >> >
> >> >
> >> > On Thu, Apr 22, 2021 at 5:12 PM Joel Fernandes <joelaf@google.com> wrote:  
> >> > >
> >> > > On Thu, Apr 22, 2021 at 4:03 PM Steven Rostedt <rostedt@goodmis.org> wrote:  
> >> > > >
> >> > > > On Thu, 22 Apr 2021 15:49:21 -0400
> >> > > > Joel Fernandes <joelaf@google.com> wrote:
> >> > > >  
> >> > > > > On Thu, Apr 22, 2021 at 3:48 PM Steven Rostedt <rostedt@goodmis.org> wrote:  
> >> > > > > >
> >> > > > > > On Thu, 22 Apr 2021 15:43:37 -0400
> >> > > > > > Joel Fernandes <joelaf@google.com> wrote:
> >> > > > > >  
> >> > > > > > > >  # trace-cmd record -e irq -e sched -e kvm -A test@32:823 -e sched  
> >> > > > > > >
> >> > > > > > > OMG, that worked, thank you Steve and Tzvetomir !!!!!  
> >> > > > > >
> >> > > > > > Technically, you can probably leave off "-e irq", but I do find it rather
> >> > > > > > useful. But then, I add "-e irq" to the guest as well. It lets me see how
> >> > > > > > interrupts transpire from the host to the guest.  
> >> > > > >
> >> > > > > Got it thanks for the tip. Will report back any issues I see.  
> >> > > >
> >> > > > And you know you can pull this up into KernelShark as well, right?
> >> > > >
> >> > > > Checkout the development version from Yordan's repository:
> >> > > >
> >> > > >
> >> > > >  $ git clone https://github.com/yordan-karadzhov/kernel-shark.git
> >> > > >  $ cd kernel-shark
> >> > > >  $ git checkout origin/yordan_devel
> >> > > >  $ cmake .
> >> > > >  $ make
> >> > > >  $ sudo make install
> >> > > >
> >> > > > Then run kernelshark with:
> >> > > >
> >> > > >  $ kernelshark trace-host.dat -a trace-guest.dat
> >> > > >
> >> > > > (obviously, using the actual names of the trace.dat files for the host and
> >> > > > the guest)
> >> > > >
> >> > > > Then you can select: Plots -> KVM Combo Plots
> >> > > >
> >> > > > Then select the "all" box, and then apply. Then you get something like this:
> >> > > >
> >> > > >   http://rostedt.org/private/ks-host-guest.png
> >> > > >
> >> > > > Where you see how the tasks mapping to the host and guest are aligned.
> >> > > >
> >> > > > That is, if everything works fine.  
> >> > >
> >> > > Yes, I sort of knew KernelShark had this support, but so glad you sent
> >> > > me more details on how to do it, I'll try it out. I am also wondering
> >> > > how the bars of the vCPUs will look like because you can have vCPU
> >> > > threads migrated to different physical CPUs. I will go try it out and
> >> > > see what comes up :-)  
> >> >
> >> > Hi all, Just wanted to report my progress today:
> >> >
> >> > When I try to open the guest+host trace with the yordan_devel branch and command
> >> > kernelshark ~/vm-host-trace/trace.dat -a ~/vm-host-trace/trace-test.dat
> >> >
> >> > I get the following in the console: https://pastebin.com/raw/EmbsyuB8
> >> >
> >> > And the GUI looks like the attached picture, I don't see any mention
> >> > of KVM like Steve sees in
> >> > http://rostedt.org/private/ks-host-guest.png . What am I missing?
> >> >
> >> > I also zipped and attached my trace files to this email. Could you
> >> > take a look at them?  
> >>
> >> Looks like there is a gap in our implementation, affecting your use
> >> case. We rely too much on the quemu guest information that we gather,
> >> which is missing on your setup. As this information is not mandatory,
> >> the implementation should not rely on it. What we need:
> >>  - PID of the process, running the guest VM. In case of KVM, we use
> >> this PID to get the KVM guest TSC clock parameters, needed for better
> >> host and guest trace timestamps synchronization. Without this PID, KVM
> >> cannot be used for timestamps synchronization. The logic should fail
> >> back to a PTP-like algorithm, which is more generic, works in all
> >> environments, but is less accurate than KVM logic.
> >>  - PIDs of each thread, running a guest virtual CPU. This is not
> >> required for the tracing, but for better trace visualisation in
> >> KernelShark. It helps to map the host task to a vCPU and to visualise
> >> them together.
> >>
> >> Currently we collect that information from quemu, is there a way to
> >> get it from crosvm ? If yes, a crosvm support can be implemented in
> >> trace-cmd. But as I said, it is not mandatory to have it for the
> >> trace, I can send you a patch next week addressing this gap in the
> >> implementation.
> >>
> >> Thanks for testing this code!
> >>  
> >> >
> >> > My kernelshark HEAD commit is: 070d657 ("kernel-shark: Add KVMCombo
> >> > plugin") . Let me know if I should be building some other commit sha.
> >> >
> >> > Adding Yordan to this email as well.
> >> >
> >> > Thanks a lot!
> >> > -Joel  
> >>
> >>
> >>
> >> --
> >> Tzvetomir (Ceco) Stoyanov
> >> VMware Open Source Technology Center  
> 
> 
> 

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 13:39:32 +0300
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> >  # trace-cmd record -e kvm_entry ssh guest taskset -c 0 ls \; taskset -c 1 cat /etc/passwd
> >  # trace-cmd report
> > [..]
> >            <...>-129042 [004]1122452427093922: kvm_entry:            vcpu 0
> >            <...>-129043 [005]1122452427148178: kvm_entry:            vcpu 1
> >            <...>-129042 [004]1122452427150380: kvm_entry:            vcpu 0
> >            <...>-129043 [005]1122452427201498: kvm_entry:            vcpu 1
> >
> > There, I see the guest vcpu 0 is controlled by the host thread with pid
> > 129042 and vcpu 1 is controlled by host thread pid 129043.  
> 
> It works only in case of one VM, if there are more than one - cannot
> map kvm_entry event to specific VM.

Deja vu!

Yes, we had this conversation a long time ago ;-)

I was thinking of doing this during the synchronization phase. We should be
able to figure out the guest host mapping. I have a vsock-client program
that uses the vsockets to talk with the guest (like netcat). And traced it
this way:

 # trace-cmd record -e sched_wakeup -e kvm_entry

And have this:

    vsock-client-159876 [000]1346877108580652: sched_wakeup:         vhost-128994:129046 [120] success=1 CPU:006

    vhost-128994-129046 [006]1346877108678708: sched_wakeup:         CPU 0/KVM:129042 [120] success=1 CPU:007

       CPU 0/KVM-129042 [007]1346877109290044: kvm_entry:            vcpu 0


Instead of looking at vsock-client, look at the current pid and see what
"vhost" it wakes up, then see what what thread it wakes up, and then see if
it calls kvm_entry. we don't even need to know if it is a vhost. Just trace
everything that our current thread wakes up and what those wake up until
something calls kvm_entry.

We have our mapping right there! And with the new libtracefs APIs,
implementing the above walk through is trivial.

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

On Mon, Apr 26, 2021 at 3:44 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 26 Apr 2021 13:58:18 +0300
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
>
> > On Fri, Apr 23, 2021 at 11:37 AM Joel Fernandes <joelaf@google.com> wrote:
> > >
> > > Apologies for the top post as I'm on Gmail mobile and only half awake at 4.30am.  I should check but can we just scrape the crosvm PIDs from the host trace itself ? The vCPU threads are in scheduler events in the host trace. Of course that wouldn't work if we don't have events. Let me know if that works for you or if I should find another way.
> > >
> > > By the way if sync is supposed to fall back to the ptp algo, why did it not fallback for me?
> >
> > Because of a bug in the code. It assumes if KVM is detected, then qemu
> > is used to run the VMs.
> >
>
> We need to find a way to do this without qemu. It's only the thread mapping
> that is missing here, nothing else. And KVM sync should still work.

The problem is to find the VM specific directory in the KVM debugfs,
where the VM TSC parameters are. The name of the directory is
/sys/kernel/debug/kvm/<some PID>-<number>/
The PID is the qemu process which runs the VM. I wonder how it looks in crosvm ?

[ ... ]




--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Dario Faggioli]

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

On Mon, 2021-04-26 at 08:56 -0400, Steven Rostedt wrote:
> On Mon, 26 Apr 2021 13:39:32 +0300
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> > > 
> > > There, I see the guest vcpu 0 is controlled by the host thread
> > > with pid
> > > 129042 and vcpu 1 is controlled by host thread pid 129043.  
> > 
> > It works only in case of one VM, if there are more than one -
> > cannot
> > map kvm_entry event to specific VM.
> 
>  # trace-cmd record -e sched_wakeup -e kvm_entry
> 
> And have this:
> 
>     vsock-client-159876 [000]1346877108580652: sched_wakeup:        
> vhost-128994:129046 [120] success=1 CPU:006
> 
>     vhost-128994-129046 [006]1346877108678708: sched_wakeup:        
> CPU 0/KVM:129042 [120] success=1 CPU:007
> 
>        CPU 0/KVM-129042 [007]1346877109290044: kvm_entry:           
> vcpu 0
> 
Mmm... This is quite interesting. But there's something I don't think
I'm understanding.


> Instead of looking at vsock-client, look at the current pid and see
> what
> "vhost" it wakes up, then see what what thread it wakes up, and then
> see if
> it calls kvm_entry. we don't even need to know if it is a vhost. Just
> trace
> everything that our current thread wakes up and what those wake up
> until
> something calls kvm_entry.
> 
So, what's the mapping (like, mapping between what and what) that we
are interested in here, and what kind of into trick with vsock-client
is helping us gather, that we don't already have by "just" looking at
the kvm_entry events?

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 --]

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

On Mon, Apr 26, 2021 at 4:24 PM Dario Faggioli <dfaggioli@suse.com> wrote:
>
> On Mon, 2021-04-26 at 08:56 -0400, Steven Rostedt wrote:
> > On Mon, 26 Apr 2021 13:39:32 +0300
> > Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> > > >
> > > > There, I see the guest vcpu 0 is controlled by the host thread
> > > > with pid
> > > > 129042 and vcpu 1 is controlled by host thread pid 129043.
> > >
> > > It works only in case of one VM, if there are more than one -
> > > cannot
> > > map kvm_entry event to specific VM.
> >
> >  # trace-cmd record -e sched_wakeup -e kvm_entry
> >
> > And have this:
> >
> >     vsock-client-159876 [000]1346877108580652: sched_wakeup:
> > vhost-128994:129046 [120] success=1 CPU:006
> >
> >     vhost-128994-129046 [006]1346877108678708: sched_wakeup:
> > CPU 0/KVM:129042 [120] success=1 CPU:007
> >
> >        CPU 0/KVM-129042 [007]1346877109290044: kvm_entry:
> > vcpu 0
> >
> Mmm... This is quite interesting. But there's something I don't think
> I'm understanding.
>
>
> > Instead of looking at vsock-client, look at the current pid and see
> > what
> > "vhost" it wakes up, then see what what thread it wakes up, and then
> > see if
> > it calls kvm_entry. we don't even need to know if it is a vhost. Just
> > trace
> > everything that our current thread wakes up and what those wake up
> > until
> > something calls kvm_entry.
> >
> So, what's the mapping (like, mapping between what and what) that we
> are interested in here, and what kind of into trick with vsock-client
> is helping us gather, that we don't already have by "just" looking at
> the kvm_entry events?

trace-cmd uses guest name to find:
 <guest name> ->  vhost cid, port
 <guest name> ->  PID of the process, running the VM
PID of the process, running the VM -> PIDs of the threads, running each vCPU

the kvm_entry event has information about mapping <thread PID> to
vCPU, from that thread PID we could find the process which runs the
whole VM. The problem is to find the VM name, vhost cid and port using
that process ID, we couldn't find any generic and reliable way to get
that mapping. That's why the current implementation uses a qemu
specific hack - VM name, vhost cid and port are written in the qemu
command line, which we get from /proc/<qemu pid> and parse. This does
not work with non-qemu VMs.

>
> 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)

--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Dario Faggioli]

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

On Mon, 2021-04-26 at 15:59 +0300, Tzvetomir Stoyanov wrote:
> On Mon, Apr 26, 2021 at 3:44 PM Steven Rostedt <rostedt@goodmis.org>
> wrote:
> > 
> > 
> > We need to find a way to do this without qemu. It's only the thread
> > mapping
> > that is missing here, nothing else. And KVM sync should still work.
> 
> The problem is to find the VM specific directory in the KVM debugfs,
> where the VM TSC parameters are. The name of the directory is
> /sys/kernel/debug/kvm/<some PID>-<number>/
> The PID is the qemu process which runs the VM. I wonder how it looks
> in crosvm ?
> 
I can't double check as I don't have a crossvm environment handy, but I
guess it looks the same, and the PID is the one of whatever task in
crossvm issues the KVM_CREATE_VM ioctl (and the fd returned by such
call).

In QEMU, such process then creates one thread for each vCPU... Again, I
don't really know for sure, but I guess it would be similar in crossvm?

If yes, AFAICT, kvm_entry events can tell us the PIDs of such threads.
So the challenge here is getting from the PID of a thread to the PID of
the process that created it.

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 --]

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 16:11:46 +0200
Dario Faggioli <dfaggioli@suse.com> wrote:

> I can't double check as I don't have a crossvm environment handy, but I
> guess it looks the same, and the PID is the one of whatever task in
> crossvm issues the KVM_CREATE_VM ioctl (and the fd returned by such
> call).
> 
> In QEMU, such process then creates one thread for each vCPU... Again, I

I'm sure all implementations will do the same. Anything else would not make
sense.

> don't really know for sure, but I guess it would be similar in crossvm?
> 
> If yes, AFAICT, kvm_entry events can tell us the PIDs of such threads.
> So the challenge here is getting from the PID of a thread to the PID of
> the process that created it.

As I stated in the other thread, we can find the thread that is running the
vCPU by following the wake ups. A vsock connection will trigger a series of
events that will eventually wake up a task that does a kvm_entry. Then you
know the thread.

Here's another run:

    vsock-client-160552 [001] 403952.847983: sched_wakeup:         vhost-128994:129046 [120] success=1 CPU:003

    vhost-128994-129046 [003] 403952.848030: sched_wakeup:         CPU 0/KVM:129042 [120] success=1 CPU:006

       CPU 0/KVM-129042 [006] 403952.848085: kvm_entry:            vcpu 0


We see that our process (PID 160552) wakes up 129046 which then wakes up
129042, which does a kvm_entry for vcpu 0. Since process 160552 is
communicating with the guest, we know that this series of events will wake
up the guest we want to map the thread and the vCPU of the guest with.

As it was thread 129042 that called kvm_entry, it's the thread that is
mapped to vcpu 0 of the guest we are tracing.

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Tzvetomir Stoyanov]

On Mon, Apr 26, 2021 at 5:51 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 26 Apr 2021 16:11:46 +0200
> Dario Faggioli <dfaggioli@suse.com> wrote:
>
> > I can't double check as I don't have a crossvm environment handy, but I
> > guess it looks the same, and the PID is the one of whatever task in
> > crossvm issues the KVM_CREATE_VM ioctl (and the fd returned by such
> > call).
> >
> > In QEMU, such process then creates one thread for each vCPU... Again, I
>
> I'm sure all implementations will do the same. Anything else would not make
> sense.
>
> > don't really know for sure, but I guess it would be similar in crossvm?
> >
> > If yes, AFAICT, kvm_entry events can tell us the PIDs of such threads.
> > So the challenge here is getting from the PID of a thread to the PID of
> > the process that created it.
>
> As I stated in the other thread, we can find the thread that is running the
> vCPU by following the wake ups. A vsock connection will trigger a series of
> events that will eventually wake up a task that does a kvm_entry. Then you
> know the thread.
>
> Here's another run:
>
>     vsock-client-160552 [001] 403952.847983: sched_wakeup:         vhost-128994:129046 [120] success=1 CPU:003
>
>     vhost-128994-129046 [003] 403952.848030: sched_wakeup:         CPU 0/KVM:129042 [120] success=1 CPU:006
>
>        CPU 0/KVM-129042 [006] 403952.848085: kvm_entry:            vcpu 0
>
>
> We see that our process (PID 160552) wakes up 129046 which then wakes up
> 129042, which does a kvm_entry for vcpu 0. Since process 160552 is
> communicating with the guest, we know that this series of events will wake
> up the guest we want to map the thread and the vCPU of the guest with.
>
> As it was thread 129042 that called kvm_entry, it's the thread that is
> mapped to vcpu 0 of the guest we are tracing.

For a complete mapping, some handshake logic should be implemented -
to force the guest to use all its CPUs, and to ensure we have the
mapping for each vCPU.
The other approach could be to look in /proc - the relation between
KVM thread 129042 and the VM process is there.

>
> -- Steve



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 18:02:58 +0300
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> > As it was thread 129042 that called kvm_entry, it's the thread that is
> > mapped to vcpu 0 of the guest we are tracing.  
> 
> For a complete mapping, some handshake logic should be implemented -
> to force the guest to use all its CPUs, and to ensure we have the
> mapping for each vCPU.

Don't we already run something on all threads? Or do we not do that for the
KVM sync?

> The other approach could be to look in /proc - the relation between
> KVM thread 129042 and the VM process is there.

What would you be looking for?

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 11:31:23 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Don't we already run something on all threads? Or do we not do that for the
> KVM sync?

I meant, all vCPUs, not "all threads".

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Dario Faggioli]

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

On Mon, 2021-04-26 at 18:02 +0300, Tzvetomir Stoyanov wrote:
> On Mon, Apr 26, 2021 at 5:51 PM Steven Rostedt <rostedt@goodmis.org>
> wrote:
> > 
> > We see that our process (PID 160552) wakes up 129046 which then
> > wakes up
> > 129042, which does a kvm_entry for vcpu 0. Since process 160552 is
> > communicating with the guest, we know that this series of events
> > will wake
> > up the guest we want to map the thread and the vCPU of the guest
> > with.
> > 
> > As it was thread 129042 that called kvm_entry, it's the thread that
> > is
> > mapped to vcpu 0 of the guest we are tracing.
> 
> For a complete mapping, some handshake logic should be implemented -
> to force the guest to use all its CPUs, and to ensure we have the
> mapping for each vCPU.
> The other approach could be to look in /proc - the relation between
> KVM thread 129042 and the VM process is there.
> 
Yeah, that was kind of my point. Any VMEnter, from any of the vCPUs
will give us a PID, the one of a vCPU thread. From that PID, we can
look up the PID of the process that created the vCPU (although, I don't
know how, except scanning).

With the PID of the creating process you can tell (e.g., still from
/proc) the number of the vm-fd, and we have everything to reach TSC
offsets in debugfs... Isn't that so?

What about the vhost cid and port? If they're on the command line (as
they are for QEMU), of course we have them in /proc too. IDK if crossvm
(and other VMMs) also have them on the  command line, though.

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 --]

Re: Instructions for clock sync for tracing host/guest

[Dario Faggioli]

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

On Mon, 2021-04-26 at 11:31 -0400, Steven Rostedt wrote:
> On Mon, 26 Apr 2021 18:02:58 +0300
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> > > 
> 
> > The other approach could be to look in /proc - the relation between
> > KVM thread 129042 and the VM process is there.
> 
> What would you be looking for?
> 
Whatever the mechanism, What you need is the PID of the process that
created the thread with PID 129042. Because that is the PID used in
debugfs.

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 --]

Re: Instructions for clock sync for tracing host/guest

[Steven Rostedt]

On Mon, 26 Apr 2021 17:38:09 +0200
Dario Faggioli <dfaggioli@suse.com> wrote:

> Yeah, that was kind of my point. Any VMEnter, from any of the vCPUs
> will give us a PID, the one of a vCPU thread. From that PID, we can
> look up the PID of the process that created the vCPU (although, I don't
> know how, except scanning).

But that's implementation specific to the creation of the VM. Can we rely
on that?

> 
> With the PID of the creating process you can tell (e.g., still from
> /proc) the number of the vm-fd, and we have everything to reach TSC
> offsets in debugfs... Isn't that so?

I'm not sure what you mean here.

> 
> What about the vhost cid and port? If they're on the command line (as
> they are for QEMU), of course we have them in /proc too. IDK if crossvm
> (and other VMMs) also have them on the  command line, though.

If possible, I'd like to avoid parsing cmdlines. We can do that for now if
the user uses libvirt and just passes the name of the guest:

 -A Fedora21

But if you pass the vsock id:

 -A guest@3:823

then all bets are off, as we do not know what implementation is running the
guest. The most robust way would be to use the trace events of the sched
wake ups as I mentioned. This way, when trace-cmd talks with the guest
agent, we can follow the wake ups and find which thread is communicating
with the guest on behalf of trace-cmd. This removes all reliance on the
user space implementation.

BTW, when checking wake ups, you need to ignore any wake up that is done in
an interrupt. As those may not be related to the communication to the guest.

-- Steve

Re: Instructions for clock sync for tracing host/guest

[Dario Faggioli]

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

On Mon, 2021-04-26 at 11:50 -0400, Steven Rostedt wrote:
> On Mon, 26 Apr 2021 17:38:09 +0200
> Dario Faggioli <dfaggioli@suse.com> wrote:
> > 
> > With the PID of the creating process you can tell (e.g., still from
> > /proc) the number of the vm-fd, and we have everything to reach TSC
> > offsets in debugfs... Isn't that so?
> 
> I'm not sure what you mean here.
> 
So:

ps -eT |grep "CPU 0/KVM"
  PID  SPID TTY          TIME CMD
 7037  7050 ?        00:26:31 CPU 0/KVM

That's vCPU 0's host task. It's a thread whose host PID is 7050. With
trace_cmd, you'll see kvm_enter events happening in task 7050, so
that's indeed a really good way to retrieve such PID.

The process that created this vCPU thread is 7037, which in my case is
in fact QEMU:

ps aux |grep 7037
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
qemu      7037  336 17.8 63578168 11647320 ?   Sl   Apr26 1489:18 /usr/bin/qemu-system-x86_64 -name guest=vm-kvm...

This QEMU process (7037) is the one that created the VM itself, with
the appropriate ioctl, which returned to it the VM-fd:

ls -lR /proc/7037/fd/*|grep kvm-vm
lrwx------ 1 qemu qemu 64 Apr 26 22:01 /proc/7037/fd/14 -> anon_inode:kvm-vm

So, in this case, it's fd 14. And, in fact, in debugfs, we have:

ls /sys/kernel/debug/kvm/ -l                                          
drwxr-xr-x 34 root root 0 Apr 26 16:41 7037-14

Hope is clearer (and ideally even useful :-P)

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 --]