linux-trace-devel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [RFC] Simple tool for VMEnters/VMExits matching and trace validation
@ 2021-04-16 16:46 Stefano De Venuto
  2021-04-16 17:47 ` Dario Faggioli
  2021-04-20  8:12 ` Yordan Karadzhov
  0 siblings, 2 replies; 10+ messages in thread
From: Stefano De Venuto @ 2021-04-16 16:46 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel, dfaggioli, Stefano De Venuto

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 @@
+#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


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-16 16:46 [RFC] Simple tool for VMEnters/VMExits matching and trace validation Stefano De Venuto
@ 2021-04-16 17:47 ` Dario Faggioli
  2021-04-16 20:48   ` Stefano De Venuto
  2021-04-20  8:12 ` Yordan Karadzhov
  1 sibling, 1 reply; 10+ messages in thread
From: Dario Faggioli @ 2021-04-16 17:47 UTC (permalink / raw)
  To: Stefano De Venuto, rostedt; +Cc: linux-trace-devel


[-- Attachment #1.1: Type: text/plain, Size: 1429 bytes --]

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
-- 
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 #1.2: 0001-Moved-kvm_entry-and-kvm_exit-tracepoints.patch --]
[-- Type: text/x-patch, Size: 3112 bytes --]

From 4a93ecd7f8354bbfa724dec6af357c23596dea64 Mon Sep 17 00:00:00 2001
From: Stefano De Venuto <stefano.devenuto99@gmail.com>
Date: Fri, 16 Apr 2021 08:58:15 +0200
Subject: [PATCH] Moved kvm_entry and kvm_exit tracepoints

---
 arch/x86/kvm/svm/svm.c |  8 ++++----
 arch/x86/kvm/vmx/vmx.c | 10 +++++-----
 2 files changed, 9 insertions(+), 9 deletions(-)

diff --git a/arch/x86/kvm/svm/svm.c b/arch/x86/kvm/svm/svm.c
index 3442d44ca53b..84c268ea3a31 100644
--- a/arch/x86/kvm/svm/svm.c
+++ b/arch/x86/kvm/svm/svm.c
@@ -3262,8 +3262,6 @@ static int handle_exit(struct kvm_vcpu *vcpu, fastpath_t exit_fastpath)
 	struct kvm_run *kvm_run = vcpu->run;
 	u32 exit_code = svm->vmcb->control.exit_code;
 
-	trace_kvm_exit(exit_code, vcpu, KVM_ISA_SVM);
-
 	/* SEV-ES guests must use the CR write traps to track CR registers. */
 	if (!sev_es_guest(vcpu->kvm)) {
 		if (!svm_is_intercept(svm, INTERCEPT_CR0_WRITE))
@@ -3744,8 +3742,6 @@ static __no_kcsan fastpath_t svm_vcpu_run(struct kvm_vcpu *vcpu)
 {
 	struct vcpu_svm *svm = to_svm(vcpu);
 
-	trace_kvm_entry(vcpu);
-
 	svm->vmcb->save.rax = vcpu->arch.regs[VCPU_REGS_RAX];
 	svm->vmcb->save.rsp = vcpu->arch.regs[VCPU_REGS_RSP];
 	svm->vmcb->save.rip = vcpu->arch.regs[VCPU_REGS_RIP];
@@ -3798,8 +3794,12 @@ static __no_kcsan fastpath_t svm_vcpu_run(struct kvm_vcpu *vcpu)
 	 */
 	x86_spec_ctrl_set_guest(svm->spec_ctrl, svm->virt_spec_ctrl);
 
+	trace_kvm_entry(vcpu);
+
 	svm_vcpu_enter_exit(vcpu, svm);
 
+	trace_kvm_exit(svm->vmcb->control.exit_code, vcpu, KVM_ISA_SVM);
+
 	/*
 	 * We do not use IBRS in the kernel. If this vCPU has used the
 	 * SPEC_CTRL MSR it may have left it on; save the value and
diff --git a/arch/x86/kvm/vmx/vmx.c b/arch/x86/kvm/vmx/vmx.c
index eb69fef57485..d0ca562999b6 100644
--- a/arch/x86/kvm/vmx/vmx.c
+++ b/arch/x86/kvm/vmx/vmx.c
@@ -6653,8 +6653,6 @@ static fastpath_t vmx_vcpu_run(struct kvm_vcpu *vcpu)
 	if (vmx->emulation_required)
 		return EXIT_FASTPATH_NONE;
 
-	trace_kvm_entry(vcpu);
-
 	if (vmx->ple_window_dirty) {
 		vmx->ple_window_dirty = false;
 		vmcs_write32(PLE_WINDOW, vmx->ple_window);
@@ -6710,9 +6708,14 @@ static fastpath_t vmx_vcpu_run(struct kvm_vcpu *vcpu)
 	 */
 	x86_spec_ctrl_set_guest(vmx->spec_ctrl, 0);
 
+	trace_kvm_entry(vcpu);
+
 	/* The actual VMENTER/EXIT is in the .noinstr.text section. */
 	vmx_vcpu_enter_exit(vcpu, vmx);
 
+	vmx->exit_reason = vmcs_read32(VM_EXIT_REASON);
+	trace_kvm_exit(vmx->exit_reason, vcpu, KVM_ISA_VMX);
+
 	/*
 	 * We do not use IBRS in the kernel. If this vCPU has used the
 	 * SPEC_CTRL MSR it may have left it on; save the value and
@@ -6772,12 +6775,9 @@ static fastpath_t vmx_vcpu_run(struct kvm_vcpu *vcpu)
 		return EXIT_FASTPATH_NONE;
 	}
 
-	vmx->exit_reason = vmcs_read32(VM_EXIT_REASON);
 	if (unlikely((u16)vmx->exit_reason == EXIT_REASON_MCE_DURING_VMENTRY))
 		kvm_machine_check();
 
-	trace_kvm_exit(vmx->exit_reason, vcpu, KVM_ISA_VMX);
-
 	if (unlikely(vmx->exit_reason & VMX_EXIT_REASONS_FAILED_VMENTRY))
 		return EXIT_FASTPATH_NONE;
 
-- 
2.30.2

\r

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

^ permalink raw reply related	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-16 17:47 ` Dario Faggioli
@ 2021-04-16 20:48   ` Stefano De Venuto
  2021-04-16 21:32     ` Steven Rostedt
  0 siblings, 1 reply; 10+ messages in thread
From: Stefano De Venuto @ 2021-04-16 20:48 UTC (permalink / raw)
  To: Dario Faggioli, rostedt; +Cc: linux-trace-devel



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
> 

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-16 20:48   ` Stefano De Venuto
@ 2021-04-16 21:32     ` Steven Rostedt
  2021-04-17  6:43       ` Dario Faggioli
  0 siblings, 1 reply; 10+ messages in thread
From: Steven Rostedt @ 2021-04-16 21:32 UTC (permalink / raw)
  To: Stefano De Venuto; +Cc: Dario Faggioli, linux-trace-devel

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


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-16 21:32     ` Steven Rostedt
@ 2021-04-17  6:43       ` Dario Faggioli
  0 siblings, 0 replies; 10+ messages in thread
From: Dario Faggioli @ 2021-04-17  6:43 UTC (permalink / raw)
  To: Steven Rostedt, Stefano De Venuto; +Cc: linux-trace-devel

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

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

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-16 16:46 [RFC] Simple tool for VMEnters/VMExits matching and trace validation Stefano De Venuto
  2021-04-16 17:47 ` Dario Faggioli
@ 2021-04-20  8:12 ` Yordan Karadzhov
  2021-04-21  2:17   ` Steven Rostedt
  2021-05-01  6:11   ` Stefano De Venuto
  1 sibling, 2 replies; 10+ messages in thread
From: Yordan Karadzhov @ 2021-04-20  8:12 UTC (permalink / raw)
  To: Stefano De Venuto, rostedt; +Cc: linux-trace-devel, dfaggioli

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




^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-20  8:12 ` Yordan Karadzhov
@ 2021-04-21  2:17   ` Steven Rostedt
  2021-04-21  9:14     ` Yordan Karadzhov
  2021-05-01  6:11     ` Stefano De Venuto
  2021-05-01  6:11   ` Stefano De Venuto
  1 sibling, 2 replies; 10+ messages in thread
From: Steven Rostedt @ 2021-04-21  2:17 UTC (permalink / raw)
  To: Yordan Karadzhov; +Cc: Stefano De Venuto, linux-trace-devel, dfaggioli

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

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-21  2:17   ` Steven Rostedt
@ 2021-04-21  9:14     ` Yordan Karadzhov
  2021-05-01  6:11     ` Stefano De Venuto
  1 sibling, 0 replies; 10+ messages in thread
From: Yordan Karadzhov @ 2021-04-21  9:14 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Stefano De Venuto, linux-trace-devel, dfaggioli


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

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-20  8:12 ` Yordan Karadzhov
  2021-04-21  2:17   ` Steven Rostedt
@ 2021-05-01  6:11   ` Stefano De Venuto
  1 sibling, 0 replies; 10+ messages in thread
From: Stefano De Venuto @ 2021-05-01  6:11 UTC (permalink / raw)
  To: Yordan Karadzhov, rostedt; +Cc: linux-trace-devel, dfaggioli

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


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [RFC] Simple tool for VMEnters/VMExits matching and trace validation
  2021-04-21  2:17   ` Steven Rostedt
  2021-04-21  9:14     ` Yordan Karadzhov
@ 2021-05-01  6:11     ` Stefano De Venuto
  1 sibling, 0 replies; 10+ messages in thread
From: Stefano De Venuto @ 2021-05-01  6:11 UTC (permalink / raw)
  To: Steven Rostedt, Yordan Karadzhov; +Cc: linux-trace-devel, dfaggioli



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
> 

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2021-05-01  6:11 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-04-16 16:46 [RFC] Simple tool for VMEnters/VMExits matching and trace validation Stefano De Venuto
2021-04-16 17:47 ` Dario Faggioli
2021-04-16 20:48   ` Stefano De Venuto
2021-04-16 21:32     ` Steven Rostedt
2021-04-17  6:43       ` Dario Faggioli
2021-04-20  8:12 ` Yordan Karadzhov
2021-04-21  2:17   ` Steven Rostedt
2021-04-21  9:14     ` Yordan Karadzhov
2021-05-01  6:11     ` Stefano De Venuto
2021-05-01  6:11   ` Stefano De Venuto

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).