| Message ID | 20210416164653.2949-1-stefano.devenuto99@gmail.com (mailing list archive) |
|---|---|
| State | RFC |
| Headers | show |
| Series | [RFC] Simple tool for VMEnters/VMExits matching and trace validation | expand |
On Fri, 2021-04-16 at 18:46 +0200, Stefano De Venuto wrote: > Add a tool in examples/ that scans a merged host + guest trace and > search for host events that are inside a vmentry/vmexit block (and > vice-versa for guest events ouside the block) and report the found > ones. > > It can be useful as a starting point for identifying issues of for > checking the effectiveness of host/guest traces synchronization, or > even for improving the placing of the tracepoints in the kernel. > > Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> > Just as an example, by using this tool we noticed that there are a bunch of host events that, despite happening before a VMEnter (and after a VMExit) were shown in the trace inside of a kvm_enter - kvm_exit "block". Stefano, do you still have an example of how the trace looks like? Can you paste it here? Stefano has also already developed the attached kernel patch. Which we plan to submit upstream as soon as we've tested properly on Intel hardware as well. But that's another story (although, feel free to provide any feedback already, if interested). Thanks and Regards
On 4/16/21 7:47 PM, Dario Faggioli wrote: > On Fri, 2021-04-16 at 18:46 +0200, Stefano De Venuto wrote: >> Add a tool in examples/ that scans a merged host + guest trace and >> search for host events that are inside a vmentry/vmexit block (and >> vice-versa for guest events ouside the block) and report the found >> ones. >> >> It can be useful as a starting point for identifying issues of for >> checking the effectiveness of host/guest traces synchronization, or >> even for improving the placing of the tracepoints in the kernel. >> >> Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> >> > Just as an example, by using this tool we noticed that there are a > bunch of host events that, despite happening before a VMEnter (and > after a VMExit) were shown in the trace inside of a kvm_enter - > kvm_exit "block". > > Stefano, do you still have an example of how the trace looks like? Can > you paste it here? > Yes. An example of those events is visible in this trace: trace.dat: CPU 0/KVM-1567 [001]14320175367012: kvm_entry: vcpu 0, rip 0xffffffff84a792b6 trace.dat: CPU 0/KVM-1567 [001]14320175253942: write_msr: c0011020, value 0 trace-tumbleweed.dat: <idle>-0 [000]14320175283462: hrtimer_cancel: hrtimer=0xffff9002fdc21a00 trace-tumbleweed.dat: <idle>-0 [000]14320175291336: hrtimer_expire_entry: hrtimer=0xffff9002fdc21a00 function=tick_sched_timer now=3601121397289 trace-tumbleweed.dat: <idle>-0 [000]14320175317345: hrtimer_expire_exit: hrtimer=0xffff9002fdc21a00 trace-tumbleweed.dat: <idle>-0 [000]14320175319329: hrtimer_start: hrtimer=0xffff9002fdc21a00 function=tick_sched_timer expires=3601125253926 softexpires=3601125253926 mode=0x0 trace.dat: CPU 0/KVM-1567 [001]14320175331517: write_msr: c0011020, value 40000000000000 trace.dat: CPU 0/KVM-1567 [001]14320175338548: kvm_wait_lapic_expire: vcpu 0: delta 534432 (late) trace.dat: CPU 0/KVM-1567 [001]14320175341750: kvm_eoi: apicid 0 vector 236 trace.dat: CPU 0/KVM-1567 [001]14320175343465: kvm_pv_eoi: apicid 0 vector 236 trace.dat: CPU 0/KVM-1567 [001]14320175345704: kvm_exit: vcpu 0 reason msr rip 0xffffffff84a792b4 info1 0x0000000000000001 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000 > Stefano has also already developed the attached kernel patch. Which we > plan to submit upstream as soon as we've tested properly on Intel > hardware as well. But that's another story (although, feel free to > provide any feedback already, if interested). > > Thanks and Regards >
On Fri, 16 Apr 2021 22:48:38 +0200 Stefano De Venuto <stefano.devenuto99@gmail.com> wrote: > On 4/16/21 7:47 PM, Dario Faggioli wrote: > > On Fri, 2021-04-16 at 18:46 +0200, Stefano De Venuto wrote: > >> Add a tool in examples/ that scans a merged host + guest trace and > >> search for host events that are inside a vmentry/vmexit block (and > >> vice-versa for guest events ouside the block) and report the found > >> ones. > >> > >> It can be useful as a starting point for identifying issues of for > >> checking the effectiveness of host/guest traces synchronization, or > >> even for improving the placing of the tracepoints in the kernel. > >> > >> Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> > >> > > Just as an example, by using this tool we noticed that there are a > > bunch of host events that, despite happening before a VMEnter (and > > after a VMExit) were shown in the trace inside of a kvm_enter - > > kvm_exit "block". > > > > Stefano, do you still have an example of how the trace looks like? Can > > you paste it here? > > > > Yes. An example of those events is visible in this trace: > > trace.dat: CPU 0/KVM-1567 [001]14320175367012: kvm_entry: vcpu 0, rip 0xffffffff84a792b6 > trace.dat: CPU 0/KVM-1567 [001]14320175253942: write_msr: c0011020, value 0 > trace-tumbleweed.dat: <idle>-0 [000]14320175283462: hrtimer_cancel: hrtimer=0xffff9002fdc21a00 > trace-tumbleweed.dat: <idle>-0 [000]14320175291336: hrtimer_expire_entry: hrtimer=0xffff9002fdc21a00 function=tick_sched_timer now=3601121397289 > trace-tumbleweed.dat: <idle>-0 [000]14320175317345: hrtimer_expire_exit: hrtimer=0xffff9002fdc21a00 > trace-tumbleweed.dat: <idle>-0 [000]14320175319329: hrtimer_start: hrtimer=0xffff9002fdc21a00 function=tick_sched_timer expires=3601125253926 softexpires=3601125253926 mode=0x0 > trace.dat: CPU 0/KVM-1567 [001]14320175331517: write_msr: c0011020, value 40000000000000 > trace.dat: CPU 0/KVM-1567 [001]14320175338548: kvm_wait_lapic_expire: vcpu 0: delta 534432 (late) > trace.dat: CPU 0/KVM-1567 [001]14320175341750: kvm_eoi: apicid 0 vector 236 > trace.dat: CPU 0/KVM-1567 [001]14320175343465: kvm_pv_eoi: apicid 0 vector 236 > trace.dat: CPU 0/KVM-1567 [001]14320175345704: kvm_exit: vcpu 0 reason msr rip 0xffffffff84a792b4 info1 0x0000000000000001 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000 Is the above with the time negotiations working fine? We do not yet support the guest shift, as we found that it was broken (I believe you reported that) and we do not have a machine available to that has that feature :-/ -- Steve > > > Stefano has also already developed the attached kernel patch. Which we > > plan to submit upstream as soon as we've tested properly on Intel > > hardware as well. But that's another story (although, feel free to > > provide any feedback already, if interested). > > > > Thanks and Regards > >
On Fri, 2021-04-16 at 17:32 -0400, Steven Rostedt wrote: > On Fri, 16 Apr 2021 22:48:38 +0200 > Stefano De Venuto <stefano.devenuto99@gmail.com> wrote: > > > > Yes. An example of those events is visible in this trace: > > > > trace.dat: CPU 0/KVM-1567 [001]14320175367012: > > kvm_entry: vcpu 0, rip 0xffffffff84a792b6 > > trace.dat: CPU 0/KVM-1567 [001]14320175253942: > > write_msr: c0011020, value 0 > > trace-tumbleweed.dat: <idle>-0 [000]14320175283462: > > hrtimer_cancel: hrtimer=0xffff9002fdc21a00 > > trace-tumbleweed.dat: <idle>-0 [000]14320175291336: > > hrtimer_expire_entry: hrtimer=0xffff9002fdc21a00 > > function=tick_sched_timer now=3601121397289 > > trace-tumbleweed.dat: <idle>-0 [000]14320175317345: > > hrtimer_expire_exit: hrtimer=0xffff9002fdc21a00 > > trace-tumbleweed.dat: <idle>-0 [000]14320175319329: > > hrtimer_start: hrtimer=0xffff9002fdc21a00 > > function=tick_sched_timer expires=3601125253926 > > softexpires=3601125253926 mode=0x0 > > trace.dat: CPU 0/KVM-1567 [001]14320175331517: > > write_msr: c0011020, value 40000000000000 > > trace.dat: CPU 0/KVM-1567 [001]14320175338548: > > kvm_wait_lapic_expire: vcpu 0: delta 534432 (late) > > trace.dat: CPU 0/KVM-1567 [001]14320175341750: > > kvm_eoi: apicid 0 vector 236 > > trace.dat: CPU 0/KVM-1567 [001]14320175343465: > > kvm_pv_eoi: apicid 0 vector 236 > > trace.dat: CPU 0/KVM-1567 [001]14320175345704: > > kvm_exit: vcpu 0 reason msr rip 0xffffffff84a792b4 > > info1 0x0000000000000001 info2 0x0000000000000000 intr_info > > 0x00000000 error_code 0x00000000 > > Is the above with the time negotiations working fine? > Yes. I think this is still with PTP. But this time, this is actually all about the host. > We do not yet support the guest shift, as we found that it was broken > (I > believe you reported that) and we do not have a machine available to > that > has that feature :-/ > Sure, but the problem here is that write_msr, kvm_wait_lapic_expire, kvm_eoi, kvm_pv_eoi in trace.dat (which is the host trace), despite happening after the VMExit, are shown before kvm_exit. This, we think, has to do to where the call to trace_kvm_exit() is in the kernel, and that's why we said we'll send a patch to move it. It was just an example of what and how one can use the simple little tool that Stefano has made on top of libkshark, as it was what helped us spot this problem. :-) Regards
Ciao Stefano, First of all, I am very happy to see you progressing so fast in the development of your VMEnters/VMExits matching analysis. I have several comments concerning the code (see below). On 16.04.21 г. 19:46, Stefano De Venuto wrote: > Add a tool in examples/ that scans a merged host + guest trace and > search for host events that are inside a vmentry/vmexit block (and > vice-versa for guest events ouside the block) and report the found > ones. > > It can be useful as a starting point for identifying issues of for > checking the effectiveness of host/guest traces synchronization, or > even for improving the placing of the tracepoints in the kernel. > > Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> > --- > examples/checker.c | 202 +++++++++++++++++++++++++++++++++++++++++++++ > 1 file changed, 202 insertions(+) > create mode 100644 examples/checker.c > > diff --git a/examples/checker.c b/examples/checker.c > new file mode 100644 > index 0000000..0b04343 > --- /dev/null > +++ b/examples/checker.c > @@ -0,0 +1,202 @@ The first problem is that this patch fails to apply. My guess is that you hand-edited the patch and removed some lines starting with "+". Note that the total number of additions and removals in the file is indicated in the line above. If this number does not match the number of lines starting with "+", the patch will fail to apply. As a general advise - try to avoid hand-editing patches unless you are certain you know what you are doing. Another general problem is that your patch seems to use CRLF for indicating new lines. This makes git produce a lot of warnings. Please fix this in version 2. > +#include <stdio.h> > +#include <stdlib.h> > +#include <string.h> > + > +#include "libkshark.h" > +#include "libkshark-tepdata.h" > + > +#define KVM_ENTRY "kvm/kvm_entry" > +#define KVM_EXIT "kvm/kvm_exit" > + > +struct custom_stream > +{ > + struct kshark_data_stream* original_stream; > + int* cpus; > +}; > + > +int is_guest(int stream_id, > + struct kshark_host_guest_map* mapping, > + int n_mapping, int* host) > +{ > + for (int i = 0; i < n_mapping; i++) { > + if (mapping[i].guest_id == stream_id) { > + *host = mapping[i].host_id; > + return 1; > + } > + } > + > + return 0; > +} > + > +void print_entry(struct kshark_entry* entry) > +{ > + struct kshark_data_stream* stream; > + char* event_name; > + int stream_id; > + > + stream = kshark_get_stream_from_entry(entry); > + event_name = kshark_get_event_name(entry); > + > + stream_id = stream->stream_id; > + printf("%d: %s-%d, %lld [%03d]:%s\t%s\n", > + stream->stream_id, > + kshark_get_task(entry), > + kshark_get_pid(entry), > + entry->ts, > + entry->cpu, > + event_name, > + kshark_get_info(entry)); > + > +} > + Remove the empty line at the end of the function. > +void print_entries(struct kshark_entry **entries, ssize_t n_entries) > +{ > + for (int i = 0; i < n_entries; ++i > + print_entry(entries[i]); > +} > + This function looks like a dead code. It must be removed if you don't use it. > +void free_data(struct kshark_context *kshark_ctx, > + struct custom_stream** custom_streams, > + struct kshark_entry** entries, int n_entries, > + struct kshark_host_guest_map* host_guest_mapping, > + int n_guest) > +{ > + struct custom_stream* custom_stream; > + > + for (int i = 0; i < kshark_ctx->n_streams; i++) { > + custom_stream = custom_streams[i]; > + > + free(custom_stream->cpus); > + free(custom_stream); > + } > + free(custom_streams); > + > + for (int i = 0; i < n_entries; i++) > + free(entries[i]); > + free(entries); > + > + kshark_tracecmd_free_hostguest_map(host_guest_mapping, n_guest); > + > + kshark_close_all(kshark_ctx); > + kshark_free(kshark_ctx); kshark_free() calls kshark_close_all() internally. No need to have both. Also, since this function is called "free_data" and kshark_free() has nothing to do with "data", it may be better to move the call of kshark_free() outside, and place it in main(). > +} > + > +int main(int argc, char **argv) > +{ > + Remove the empty line here. > + struct kshark_host_guest_map* host_guest_mapping; > + struct custom_stream** custom_streams; > + struct custom_stream* custom_stream; > + struct custom_stream* host_stream; > + struct kshark_data_stream* stream; > + struct kshark_context* kshark_ctx; > + struct kshark_entry** entries; > + struct kshark_entry* current; > + ssize_t n_entries; > + char* event_name; > + char* token; > + int n_guest; > + char* info; > + int host; > + int v_i; > + int sd; > + > + kshark_ctx = NULL; > + if (!kshark_instance(&kshark_ctx)) > + return 1; > + > + custom_streams = malloc(sizeof(*custom_streams) * (argc-1)); > + > + for (int i = 1; i < argc; i++) { > + sd = kshark_open(kshark_ctx, argv[i]); > + if (sd < 0) { > + kshark_free(kshark_ctx); > + return 1; > + } > + > + kshark_tep_init_all_buffers(kshark_ctx, sd); > + > + custom_stream = malloc(sizeof(*custom_stream)); > + custom_stream->original_stream = kshark_get_data_stream(kshark_ctx, sd); > + custom_stream->cpus = malloc(custom_stream->original_stream->n_cpus * sizeof(int)); > + memset(custom_stream->cpus, -1, custom_stream->original_stream->n_cpus * sizeof(int)); Add a comment explaining why you are doing this. > + > + custom_streams[i-1] = custom_stream; > + } > + > + host_guest_mapping = NULL; > + n_guest = kshark_tracecmd_get_hostguest_mapping(&host_guest_mapping); > + if (n_guest < 0) { > + printf("Failed mapping: %d\n", n_guest); > + return 1; > + } > + > + entries = NULL; > + n_entries = kshark_load_all_entries(kshark_ctx, &entries); > + > + for (int i = 0; i < n_entries; ++i) { > + current = entries[i]; > + > + stream = kshark_get_stream_from_entry(current); > + event_name = kshark_get_event_name(current); > + > + custom_stream = custom_streams[stream->stream_id]; > + > + if (!strcmp(event_name, KVM_ENTRY) || !strcmp(event_name, KVM_EXIT)) { > + if (!strcmp(event_name, KVM_ENTRY)) { > + > + /* > + * The recovering process of the vCPU field of the kvm_entry event > + * is done by splitting the info field. > + */ > + info = kshark_get_info(current); > + > + token = strtok(info, " "); > + token = strtok(NULL, " "); > + > + /* Removing the last comma */ > + token[strlen(token) - 1] = '\0'; > + > + custom_stream->cpus[current->cpu] = atoi(token); It will be better if you make the recovering of the vCPU above a static helper function. > + > + free(info); > + } else { > + custom_stream->cpus[current->cpu] = -1; > + } > + > + } else { > + > + /* > + * If the event comes from a guest, recover the pCPU where the event was executed > + * and check if it's NOT OUTSIDE a kvm_entry/kvm_exit block. > + */ > + if (is_guest(stream->stream_id, host_guest_mapping, n_guest, &host)) { > + host_stream = custom_streams[host]; > + > + for (v_i = 0; v_i < host_stream->original_stream->n_cpus; v_i++) { > + if (current->cpu == host_stream->cpus[v_i]) > + break; > + } > + > + if (v_i == host_stream->original_stream->n_cpus) { > + printf("%d G out:\t", i); > + print_entry(entries[i]); > + } > + > + /* > + * If the event comes from a host, recover the CPU that executed the event > + * and check if it's NOT INSIDE a kvm_entry/kvm_exit block. > + */ > + } else { > + if (custom_stream->cpus[current->cpu] != -1) { > + printf("%d H in:\t", i); > + print_entry(entries[i]); > + } > + } > + } > + } > + > + free_data(kshark_ctx, custom_streams, entries, n_entries, host_guest_mapping, n_guest); > +} I do not see how you build the tool. I guess you edited CMakeLists.txt. This must be part of the patch as well. Looking forward to see version 2. Best, Yordan
On Tue, 20 Apr 2021 11:12:59 +0300 Yordan Karadzhov <y.karadz@gmail.com> wrote: > > diff --git a/examples/checker.c b/examples/checker.c > > new file mode 100644 > > index 0000000..0b04343 > > --- /dev/null > > +++ b/examples/checker.c > > @@ -0,0 +1,202 @@ > > The first problem is that this patch fails to apply. My guess is that > you hand-edited the patch and removed some lines starting with "+". Note > that the total number of additions and removals in the file is indicated > in the line above. If this number does not match the number of lines > starting with "+", the patch will fail to apply. > > As a general advise - try to avoid hand-editing patches unless you are > certain you know what you are doing. Or hand edit the patches using emacs ;-) That's because emacs has a "patch mode" that updates those numbers when you modify the patch! -- Steve
On 21.04.21 г. 5:17, Steven Rostedt wrote: > On Tue, 20 Apr 2021 11:12:59 +0300 > Yordan Karadzhov <y.karadz@gmail.com> wrote: > > >>> diff --git a/examples/checker.c b/examples/checker.c >>> new file mode 100644 >>> index 0000000..0b04343 >>> --- /dev/null >>> +++ b/examples/checker.c >>> @@ -0,0 +1,202 @@ >> The first problem is that this patch fails to apply. My guess is that >> you hand-edited the patch and removed some lines starting with "+". Note >> that the total number of additions and removals in the file is indicated >> in the line above. If this number does not match the number of lines >> starting with "+", the patch will fail to apply. >> >> As a general advise - try to avoid hand-editing patches unless you are >> certain you know what you are doing. > Or hand edit the patches using emacs ;-) > > That's because emacs has a "patch mode" that updates those numbers when > you modify the patch! Cool! I didn't know that. Y. > -- Steve
Ciao Yordan, Thanks so much for the comments! I've just sent the version 2 addressing them. On 4/20/21 10:12 AM, Yordan Karadzhov wrote: > Ciao Stefano, > > First of all, I am very happy to see you progressing so fast in the > development of your VMEnters/VMExits matching analysis. I have several > comments concerning the code (see below). > > On 16.04.21 г. 19:46, Stefano De Venuto wrote: >> Add a tool in examples/ that scans a merged host + guest trace and >> search for host events that are inside a vmentry/vmexit block (and >> vice-versa for guest events ouside the block) and report the found >> ones. >> >> It can be useful as a starting point for identifying issues of for >> checking the effectiveness of host/guest traces synchronization, or >> even for improving the placing of the tracepoints in the kernel. >> >> Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> >> --- >> examples/checker.c | 202 +++++++++++++++++++++++++++++++++++++++++++++ >> 1 file changed, 202 insertions(+) >> create mode 100644 examples/checker.c >> >> diff --git a/examples/checker.c b/examples/checker.c >> new file mode 100644 >> index 0000000..0b04343 >> --- /dev/null >> +++ b/examples/checker.c >> @@ -0,0 +1,202 @@ > > The first problem is that this patch fails to apply. My guess is that > you hand-edited the patch and removed some lines starting with "+". Note > that the total number of additions and removals in the file is indicated > in the line above. If this number does not match the number of lines > starting with "+", the patch will fail to apply. > > As a general advise - try to avoid hand-editing patches unless you are > certain you know what you are doing. > Ok, thanks for the advice! >> + >> + custom_streams[i-1] = custom_stream; >> + } >> + >> + host_guest_mapping = NULL; >> + n_guest = >> kshark_tracecmd_get_hostguest_mapping(&host_guest_mapping); >> + if (n_guest < 0) { >> + printf("Failed mapping: %d\n", n_guest); >> + return 1; >> + } >> + >> + entries = NULL; >> + n_entries = kshark_load_all_entries(kshark_ctx, &entries); >> + >> + for (int i = 0; i < n_entries; ++i) { >> + current = entries[i]; >> + >> + stream = kshark_get_stream_from_entry(current); >> + event_name = kshark_get_event_name(current); >> + >> + custom_stream = custom_streams[stream->stream_id]; >> + >> + if (!strcmp(event_name, KVM_ENTRY) || !strcmp(event_name, >> KVM_EXIT)) { >> + if (!strcmp(event_name, KVM_ENTRY)) { >> + >> + /* >> + * The recovering process of the vCPU field of the >> kvm_entry event >> + * is done by splitting the info field. >> + */ >> + info = kshark_get_info(current); >> + >> + token = strtok(info, " "); >> + token = strtok(NULL, " "); >> + >> + /* Removing the last comma */ >> + token[strlen(token) - 1] = '\0'; >> + >> + custom_stream->cpus[current->cpu] = atoi(token); > > It will be better if you make the recovering of the vCPU above a static > helper function. > I totally replaced that method since with kshark_read_event_field_int(entry, "vcpu_id", &vcpu) I can get this information in such a cleaner way! Also more robust, since plugins can remove the vcpu field from the info. Regards, Stefano
On 4/21/21 4:17 AM, Steven Rostedt wrote: > On Tue, 20 Apr 2021 11:12:59 +0300 > Yordan Karadzhov <y.karadz@gmail.com> wrote: > > >>> diff --git a/examples/checker.c b/examples/checker.c >>> new file mode 100644 >>> index 0000000..0b04343 >>> --- /dev/null >>> +++ b/examples/checker.c >>> @@ -0,0 +1,202 @@ >> >> The first problem is that this patch fails to apply. My guess is that >> you hand-edited the patch and removed some lines starting with "+". Note >> that the total number of additions and removals in the file is indicated >> in the line above. If this number does not match the number of lines >> starting with "+", the patch will fail to apply. >> >> As a general advise - try to avoid hand-editing patches unless you are >> certain you know what you are doing. > > Or hand edit the patches using emacs ;-) > > That's because emacs has a "patch mode" that updates those numbers when > you modify the patch! Oh, I didn't know about this kind of mode in emacs. :-O I will surely try it, thanks! Regards, Stefano > > -- Steve >
diff --git a/examples/checker.c b/examples/checker.c new file mode 100644 index 0000000..0b04343 --- /dev/null +++ b/examples/checker.c @@ -0,0 +1,202 @@ +#include <stdio.h> +#include <stdlib.h> +#include <string.h> + +#include "libkshark.h" +#include "libkshark-tepdata.h" + +#define KVM_ENTRY "kvm/kvm_entry" +#define KVM_EXIT "kvm/kvm_exit" + +struct custom_stream +{ + struct kshark_data_stream* original_stream; + int* cpus; +}; + +int is_guest(int stream_id, + struct kshark_host_guest_map* mapping, + int n_mapping, int* host) +{ + for (int i = 0; i < n_mapping; i++) { + if (mapping[i].guest_id == stream_id) { + *host = mapping[i].host_id; + return 1; + } + } + + return 0; +} + +void print_entry(struct kshark_entry* entry) +{ + struct kshark_data_stream* stream; + char* event_name; + int stream_id; + + stream = kshark_get_stream_from_entry(entry); + event_name = kshark_get_event_name(entry); + + stream_id = stream->stream_id; + printf("%d: %s-%d, %lld [%03d]:%s\t%s\n", + stream->stream_id, + kshark_get_task(entry), + kshark_get_pid(entry), + entry->ts, + entry->cpu, + event_name, + kshark_get_info(entry)); + +} + +void print_entries(struct kshark_entry **entries, ssize_t n_entries) +{ + for (int i = 0; i < n_entries; ++i + print_entry(entries[i]); +} + +void free_data(struct kshark_context *kshark_ctx, + struct custom_stream** custom_streams, + struct kshark_entry** entries, int n_entries, + struct kshark_host_guest_map* host_guest_mapping, + int n_guest) +{ + struct custom_stream* custom_stream; + + for (int i = 0; i < kshark_ctx->n_streams; i++) { + custom_stream = custom_streams[i]; + + free(custom_stream->cpus); + free(custom_stream); + } + free(custom_streams); + + for (int i = 0; i < n_entries; i++) + free(entries[i]); + free(entries); + + kshark_tracecmd_free_hostguest_map(host_guest_mapping, n_guest); + + kshark_close_all(kshark_ctx); + kshark_free(kshark_ctx); +} + +int main(int argc, char **argv) +{ + + struct kshark_host_guest_map* host_guest_mapping; + struct custom_stream** custom_streams; + struct custom_stream* custom_stream; + struct custom_stream* host_stream; + struct kshark_data_stream* stream; + struct kshark_context* kshark_ctx; + struct kshark_entry** entries; + struct kshark_entry* current; + ssize_t n_entries; + char* event_name; + char* token; + int n_guest; + char* info; + int host; + int v_i; + int sd; + + kshark_ctx = NULL; + if (!kshark_instance(&kshark_ctx)) + return 1; + + custom_streams = malloc(sizeof(*custom_streams) * (argc-1)); + + for (int i = 1; i < argc; i++) { + sd = kshark_open(kshark_ctx, argv[i]); + if (sd < 0) { + kshark_free(kshark_ctx); + return 1; + } + + kshark_tep_init_all_buffers(kshark_ctx, sd); + + custom_stream = malloc(sizeof(*custom_stream)); + custom_stream->original_stream = kshark_get_data_stream(kshark_ctx, sd); + custom_stream->cpus = malloc(custom_stream->original_stream->n_cpus * sizeof(int)); + memset(custom_stream->cpus, -1, custom_stream->original_stream->n_cpus * sizeof(int)); + + custom_streams[i-1] = custom_stream; + } + + host_guest_mapping = NULL; + n_guest = kshark_tracecmd_get_hostguest_mapping(&host_guest_mapping); + if (n_guest < 0) { + printf("Failed mapping: %d\n", n_guest); + return 1; + } + + entries = NULL; + n_entries = kshark_load_all_entries(kshark_ctx, &entries); + + for (int i = 0; i < n_entries; ++i) { + current = entries[i]; + + stream = kshark_get_stream_from_entry(current); + event_name = kshark_get_event_name(current); + + custom_stream = custom_streams[stream->stream_id]; + + if (!strcmp(event_name, KVM_ENTRY) || !strcmp(event_name, KVM_EXIT)) { + if (!strcmp(event_name, KVM_ENTRY)) { + + /* + * The recovering process of the vCPU field of the kvm_entry event + * is done by splitting the info field. + */ + info = kshark_get_info(current); + + token = strtok(info, " "); + token = strtok(NULL, " "); + + /* Removing the last comma */ + token[strlen(token) - 1] = '\0'; + + custom_stream->cpus[current->cpu] = atoi(token); + + free(info); + } else { + custom_stream->cpus[current->cpu] = -1; + } + + } else { + + /* + * If the event comes from a guest, recover the pCPU where the event was executed + * and check if it's NOT OUTSIDE a kvm_entry/kvm_exit block. + */ + if (is_guest(stream->stream_id, host_guest_mapping, n_guest, &host)) { + host_stream = custom_streams[host]; + + for (v_i = 0; v_i < host_stream->original_stream->n_cpus; v_i++) { + if (current->cpu == host_stream->cpus[v_i]) + break; + } + + if (v_i == host_stream->original_stream->n_cpus) { + printf("%d G out:\t", i); + print_entry(entries[i]); + } + + /* + * If the event comes from a host, recover the CPU that executed the event + * and check if it's NOT INSIDE a kvm_entry/kvm_exit block. + */ + } else { + if (custom_stream->cpus[current->cpu] != -1) { + printf("%d H in:\t", i); + print_entry(entries[i]); + } + } + } + } + + free_data(kshark_ctx, custom_streams, entries, n_entries, host_guest_mapping, n_guest); +} -- 2.30.2
Add a tool in examples/ that scans a merged host + guest trace and search for host events that are inside a vmentry/vmexit block (and vice-versa for guest events ouside the block) and report the found ones. It can be useful as a starting point for identifying issues of for checking the effectiveness of host/guest traces synchronization, or even for improving the placing of the tracepoints in the kernel. Signed-off-by: Stefano De Venuto <stefano.devenuto99@gmail.com> --- examples/checker.c | 202 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 202 insertions(+) create mode 100644 examples/checker.c