KVM: perf: a smart tool to analyse kvm events

arch/x86/kvm/x86.c +0 -0

 	handled = ops->read_write_mmio(vcpu, gpa, bytes, val);
 	if (handled == bytes)
 		return X86EMUL_CONTINUE;

Quoted 5 lines · Xiao Guangrong

In current code, we use KVM_TRACE_MMIO_READ to trace mmio read event which only can be completed immediately, instead of it, we trace the time when read event occur, then cooperate with then later patch, we can know the time of mmio read emulation

arch/x86/kvm/x86.c mmio: · line 3743

Quoted 5 lines

arch/x86/kvm/x86.c +1 -0

@@ -3744,6 +3740,8 @@ mmio:
 	/*
 	 * Is this MMIO handled locally?
 	 */
+	trace_kvm_mmio(write ? KVM_TRACE_MMIO_WRITE : KVM_TRACE_MMIO_READ,

It's better to push the conditional to the trace event itself, so it's only evaluated if tracing is enabled.

arch/x86/kvm/x86.c mmio: · line 3744

Quoted 1 line

arch/x86/kvm/x86.c +1 -0

+			bytes, gpa, *(u64 *)val);

We get the wrong value for reads here, no?

Can't we leave the code as is, and infer the start of the event from the last kvm_exit trace?

- trace vcpu_id for these events

- add kvm_mmio_done to trace the time when mmio/ioport emulation is completed

Quoted 1 line · Xiao Guangrong

- trace vcpu_id for these events

We can infer the vcpu id from the kvm_entry tracepoints, no?

Quoted 1 line

- add kvm_mmio_done to trace the time when mmio/ioport emulation is completed

ditto?

Relying on the existing tracepoints will make the tool work on older kernels.

Quoted 5 lines · Avi Kivity

Quoted 1 line · Xiao Guangrong

- trace vcpu_id for these events

We can infer the vcpu id from the kvm_entry tracepoints, no?

Thanks for your review, Avi!

Hmm. i think it is hard to do since the vcpu thread can be scheduled anytime, one example is as follow:

CPU 0

kvm_entry vcpu 0
......
kvm_entry vcpu 1
......
event1 occurs
......
event2 occurs

It is hard to know the event belong to which kvm_entry?

Quoted 4 lines

Quoted 1 line

- add kvm_mmio_done to trace the time when mmio/ioport emulation is completed

ditto?

I think is ok to get the event end time by using kvm_entry.

Quoted 1 line

Quoted 3 lines

Relying on the existing tracepoints will make the tool work on older kernels.

We can drop all new events, but unfortunately, the information of the origin tracepoints is not enough, at least vcpu_id need be traced in theses events to match its events. Yes?

Quoted 40 lines · Xiao Guangrong

Quoted 5 lines · Avi Kivity

Quoted 1 line · Xiao Guangrong

- trace vcpu_id for these events

We can infer the vcpu id from the kvm_entry tracepoints, no?

Thanks for your review, Avi!

Hmm. i think it is hard to do since the vcpu thread can be scheduled anytime, one example is as follow:

CPU 0

kvm_entry vcpu 0
......
kvm_entry vcpu 1
......
event1 occurs
......
event2 occurs

It is hard to know the event belong to which kvm_entry?

Quoted 4 lines

Quoted 1 line

- add kvm_mmio_done to trace the time when mmio/ioport emulation is completed

ditto?

I think is ok to get the event end time by using kvm_entry.

Quoted 4 lines

Relying on the existing tracepoints will make the tool work on older kernels.

Quoted 3 lines

We can drop all new events, but unfortunately, the information of the origin tracepoints is not enough, at least vcpu_id need be traced in theses events to match its events. Yes?

Yes, and if you don't add completed events, you'll have to use kvm_entry whose collection adds a lot of overhead.

Quoted 10 lines

Quoted 9 lines

Quoted 4 lines

Relying on the existing tracepoints will make the tool work on older kernels.

We can drop all new events, but unfortunately, the information of the origin tracepoints is not enough, at least vcpu_id need be traced in theses events to match its events. Yes?

Quoted 2 lines

Yes, and if you don't add completed events, you'll have to use kvm_entry whose collection adds a lot of overhead.

vcpus run as threads and hence have their own tid which is available in the perf samples.

There is an ongoing 'discussion' about modifying existing tracepoints which your proposed patch violates. This is the start of it:

Quoted 3 lines

There is an ongoing 'discussion' about modifying existing tracepoints which your proposed patch violates. This is the start of it:

Hmm, i think we can still add completed tracepoints in the new version kernel, if old version kernel is used, we can fall back to use kvm_entry instead?

And there is a exception for mmio read, in current code, the mmio read event is actually used to trace the time when then read emulation is completed, i think we can add a tracepoint like mmio_read_begin to trace the start time of mmio read. So:
- for the new kernel, we use mmio_read_begion and kvm_mmio(READ...) to calculate start time and end time.
- for the old kernel, we use kvm_exit and kvm_mmio(READ...) to calculate start time and end time.

Your idea?

Quoted 5 lines · Avi Kivity

Quoted 1 line · Xiao Guangrong

- trace vcpu_id for these events

We can infer the vcpu id from the kvm_entry tracepoints, no?

Thanks for your review, Avi!

Hmm. i think it is hard to do since the vcpu thread can be scheduled anytime, one example is as follow:

CPU 0

kvm_entry vcpu 0
......
kvm_entry vcpu 1
......
event1 occurs
......
event2 occurs

It is hard to know the event belong to which kvm_entry?

Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly

Usage:
perf kvm-events record

perf kvm-events report

tools/perf/builtin-kvm-events.c new file +4 -0

+static const char *get_exit_reason(long isa, u64 exit_code)
+{
+	int table_size = ARRAY_SIZE(svm_exit_reasons);
+	struct exit_reasons_table *table = svm_exit_reasons;

(quoted diff) +2 -0

+	return key;
+}

Quoted 4 lines · Xiao Guangrong

Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly

Usage:
perf kvm-events record

Why not 'perf record -e kvm'?

Quoted 2 lines

perf kvm-events report

Quoted 4 lines

tools/perf/builtin-kvm-events.c new file +4 -0

+static const char *get_exit_reason(long isa, u64 exit_code)
+{
+	int table_size = ARRAY_SIZE(svm_exit_reasons);
+	struct exit_reasons_table *table = svm_exit_reasons;

tools/perf/builtin-kvm-events.c line 266

Quoted 10 lines

tools/perf/builtin-kvm-events.c new file +10 -0

+
+
+	if (isa == 1) {
+		table = vmx_exit_reasons;
+		table_size = ARRAY_SIZE(vmx_exit_reasons);
+	}
+
+	while (table_size--) {
+		if (table->exit_code == exit_code)
+			return table->reason;

... table[exit_code] ...

tools/perf/builtin-kvm-events.c line 271

Quoted 5 lines

tools/perf/builtin-kvm-events.c new file +5 -0

+		table++;
+	}
+
+	die("unkonw kvm exit code:%ld on %s\n", exit_code, isa == 1 ?
+						"VMX" : "SVM");

"unknown"

tools/perf/builtin-kvm-events.c line 280

Quoted 3 lines

tools/perf/builtin-kvm-events.c new file +3 -0

+
+struct kvm_events_ops {
+	bool (*is_begain_event)(struct event *event, void *data);

begin

Quoted 8 lines

tools/perf/builtin-kvm-events.c new file +8 -0

+	bool (*is_end_event)(struct event *event);
+	struct event_key (*get_key)(struct event *event, void *data);
+	void (*decode_key)(struct event_key *key, char decode[20]);
+	const char *name;
+};
+
+
+static struct event_key exit_event_get_key(struct event *event, void *data)

tools/perf/builtin-kvm-events.c line 302

Quoted 5 lines

tools/perf/builtin-kvm-events.c new file +5 -0

+{
+	struct event_key key;
+
+	key.key = raw_field_value(event, "exit_reason", data);
+	key.info = raw_field_value(event, "isa", data);

"isa" is not available on all kernel versions; need to fall back to /proc/cpuid detection.

Quoted 7 lines · Avi Kivity

Quoted 4 lines · Xiao Guangrong

Add 'perf kvm-events' support to analyze kvm vmexit/mmio/ioport smartly

Usage:
perf kvm-events record

Why not 'perf record -e kvm'?

It works, many perf tools have this style, like:
perf lock record,
perf sched record,
perf kmem record,

I think the reason is that only enable the tracepoints we need to avoid unnecessary overload so that the result is more exacter.

Quoted 7 lines

tools/perf/builtin-kvm-events.c line 266

Quoted 4 lines

tools/perf/builtin-kvm-events.c new file +4 -0

+
+	while (table_size--) {
+		if (table->exit_code == exit_code)
+			return table->reason;

... table[exit_code] ...

Actually, this array is not indexed by exit_code, it means:
table[exit_code].exit_code != exit_code.

+       { SVM_EXIT_MONITOR,                     "monitor" }, \
+       { SVM_EXIT_MWAIT,                       "mwait" }, \
+       { SVM_EXIT_XSETBV,                      "xsetbv" }, \
+       { SVM_EXIT_NPF,                         "npf" }

tools/perf/builtin-kvm-events.c new file +35 -0

+}
+
+static struct kvm_events_ops exit_events = {
+       .is_begain_event = exit_event_begain,
+       .is_end_event = exit_event_end,
+       .get_key = exit_event_get_key,
+       .decode_key = exit_event_decode_key,
+       .name = "VM-EXIT"
+};
+
+#define KVM_TRACE_MMIO_READ_UNSATISFIED 0
+#define KVM_TRACE_MMIO_READ 1
+#define KVM_TRACE_MMIO_WRITE 2
+static bool mmio_event_begain(struct event *event, void *data)
+{
+       if (!strcmp(event->name, "kvm_mmio")) {
+               long type = raw_field_value(event, "type", data);
+
+               if (type != KVM_TRACE_MMIO_READ_UNSATISFIED)
+                       return true;
+       };
+
+       return false;
+}
+
+static bool mmio_event_end(struct event *event)
+{
+       return !strcmp(event->name, "kvm_mmio_done");
+}
+
+static struct event_key mmio_event_get_key(struct event *event, void *data)
+{
+       struct event_key key;
+
+       key.key = raw_field_value(event, "gpa", data);

tools/perf/Documentation/perf-kvm-events.txt line 16

Quoted 4 lines · Xiao Guangrong

tools/perf/Documentation/perf-kvm-events.txt new file +4 -0

+DESCRIPTION
+-----------
+You can analyze some crucial events and statistics with this
+'perf kvm-events' command.

This line is very general and does not explain which events/statistics can be collected or how you can use that information. I suggest making this description more specific. Explain that this subcommand observers kvm.ko tracepoints and annotates/decodes them with additional information (this is why I would use this command and not raw perf record -e kvm:\*).

Quoted 4 lines

+ � � � { SVM_EXIT_MONITOR, � � � � � � � � � � "monitor" }, \
+ � � � { SVM_EXIT_MWAIT, � � � � � � � � � � � "mwait" }, \
+ � � � { SVM_EXIT_XSETBV, � � � � � � � � � � �"xsetbv" }, \
+ � � � { SVM_EXIT_NPF, � � � � � � � � � � � � "npf" }

All this copy-paste could be avoided by sharing this stuff with the arch/x86/kvm/ code.

tools/perf/builtin-kvm-events.c

Quoted 6 lines

tools/perf/builtin-kvm-events.c new file +6 -0

+static void exit_event_decode_key(struct event_key *key, char decode[20])
+{
+ � � � const char *exit_reason = get_exit_reason(key->info, key->key);
+
+ � � � memset(decode, 0, 20);
+ � � � strncpy(decode, exit_reason, 20);

This is a bad pattern to follow when using strncpy(3) because if there was a strlen(exit_reason) == 20 string then decode[] would not be NUL-terminated. Right now it's safe but it's better to just use strlcpy() and drop the memset(3).

Review

Quoted 5 lines

(quoted diff) +5 -0

+static void mmio_event_decode_key(struct event_key *key, char decode[20])
+{
+ � � � memset(decode, 0, 20);
+ � � � sprintf(decode, "%#lx:%s", key->key,
+ � � � � � � � key->info == KVM_TRACE_MMIO_READ ? "R" : "W");

Please drop the memset and use snprintf(3) instead of sprintf(3). It places the NUL-terminator and ensures you don't exceed the buffer size.

Same pattern below.

tools/perf/Documentation/perf-kvm-events.txt line 16

Quoted 4 lines · Xiao Guangrong

tools/perf/Documentation/perf-kvm-events.txt new file +4 -0

+DESCRIPTION
+-----------
+You can analyze some crucial events and statistics with this
+'perf kvm-events' command.

This line is very general and does not explain which events/statistics can be collected or how you can use that information. I suggest making this description more specific. Explain that this subcommand observers kvm.ko tracepoints and annotates/decodes them with additional information (this is why I would use this command and not raw perf record -e kvm:\*).

Quoted 4 lines

+       { SVM_EXIT_MONITOR,                     "monitor" }, \
+       { SVM_EXIT_MWAIT,                       "mwait" }, \
+       { SVM_EXIT_XSETBV,                      "xsetbv" }, \
+       { SVM_EXIT_NPF,                         "npf" }

All this copy-paste could be avoided by sharing this stuff with the arch/x86/kvm/ code.

Quoted 3 lines

All this copy-paste could be avoided by sharing this stuff with the arch/x86/kvm/ code.

Yes, same for KVM_MAX_VCPUS.

This tool is very like xenoprof(if i remember correctly), and traces kvm events smartly. currently, it supports vmexit/mmio/ioport events.

Usage:
- to trace kvm events:

# ./perf kvm-events record

- show the result

# ./perf kvm-events report

Some output are as follow:

# ./perf kvm-events report
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

VM-EXIT Samples Samples% Time% Avg time

APIC_ACCESS 438107 44.89% 6.20% 17.91us

  EXTERNAL_INTERRUPT     219226        22.46%         8.01%        46.20us
      IO_INSTRUCTION     122651        12.57%         1.88%        19.44us
       EPT_VIOLATION      83110         8.52%         1.36%        20.75us
   PENDING_INTERRUPT      37055         3.80%         0.16%         5.38us
               CPUID      32718         3.35%         0.08%         3.15us
       EXCEPTION_NMI      23601         2.42%         0.17%         8.87us
                 HLT      15424         1.58%        82.12%      6735.06us
           CR_ACCESS       4089         0.42%         0.02%         6.08us

Total Samples:975981, Total events handled time:126502464.88us.

The default event to be analysed is vmexit, we can use --event to specify it, for example, if we want to trace mmio event:

# ./perf kvm-events report --event mmio
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

         MMIO Access    Samples      Samples%         Time%        Avg time

        0xfee00380:W     196589        64.95%        70.01%         3.83us
        0xfee00310:W      35356        11.68%         6.48%         1.97us
        0xfee00300:W      35356        11.68%        16.37%         4.97us
        0xfee00300:R      35356        11.68%         7.14%         2.17us

Total Samples:302657, Total events handled time:1074746.01us.

We can use --vcpu to specify which vcpu is traced:
root@localhost perf]# ./perf kvm-events report --event mmio --vcpu 1
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'

Analyze events for VCPU 1:

         MMIO Access    Samples      Samples%         Time%        Avg time

        0xfee00380:W      58041        71.20%        74.90%         3.70us
        0xfee00310:W       7826         9.60%         5.28%         1.93us
        0xfee00300:W       7826         9.60%        13.82%         5.06us
        0xfee00300:R       7826         9.60%         6.01%         2.20us

Total Samples:81519, Total events handled time:286577.81us.

And, '--key' is used to sort the result, the possible value sample (default, the result is sorted by samples number), time(the result is sorted by time%):

# ./perf kvm-events report --key time
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

VM-EXIT Samples Samples% Time% Avg time

HLT 15424 1.58% 82.12% 6735.06us

  EXTERNAL_INTERRUPT     219226        22.46%         8.01%        46.20us
         APIC_ACCESS     438107        44.89%         6.20%        17.91us
      IO_INSTRUCTION     122651        12.57%         1.88%        19.44us
       EPT_VIOLATION      83110         8.52%         1.36%        20.75us
       EXCEPTION_NMI      23601         2.42%         0.17%         8.87us
   PENDING_INTERRUPT      37055         3.80%         0.16%         5.38us
               CPUID      32718         3.35%         0.08%         3.15us
           CR_ACCESS       4089         0.42%         0.02%         6.08us

Total Samples:975981, Total events handled time:126502464.88us.

I hope guys will like it and any comments are welcome! :)

Quoted 1 line

Total Samples:975981, Total events handled time:126502464.88us.

Nice! If we can have a live version as well, this can replace kvm_stat.

The average numbers are really high. Like a factor of 3x-4x off. Would be good to print the standard deviation and see why. Maybe it's due to the tracing overhead.

Quoted 10 lines

The default event to be analysed is vmexit, we can use --event to specify it, for example, if we want to trace mmio event:

# ./perf kvm-events report --event mmio
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

Quoted 6 lines

         MMIO Access    Samples      Samples%         Time%        Avg time

        0xfee00380:W     196589        64.95%        70.01%         3.83us
        0xfee00310:W      35356        11.68%         6.48%         1.97us
        0xfee00300:W      35356        11.68%        16.37%         4.97us
        0xfee00300:R      35356        11.68%         7.14%         2.17us

These are more reasonable (though still high - 5us for an ICR write?)

Quoted 3 lines

Total Samples:975981, Total events handled time:126502464.88us.

I hope guys will like it and any comments are welcome! :)

I think it's great! A live version would be a nice addition too.

Please copy the perf userspace maintainers to get more detailed review in the next version.

This tool is very like xenoprof(if i remember correctly), and traces kvm events smartly. currently, it supports vmexit/mmio/ioport events.

Usage:
- to trace kvm events:

# ./perf kvm-events record

- show the result

# ./perf kvm-events report

Some output are as follow:

# ./perf kvm-events report
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

VM-EXIT Samples Samples% Time% Avg time

APIC_ACCESS 438107 44.89% 6.20% 17.91us

  EXTERNAL_INTERRUPT     219226        22.46%         8.01%        46.20us
      IO_INSTRUCTION     122651        12.57%         1.88%        19.44us
       EPT_VIOLATION      83110         8.52%         1.36%        20.75us
   PENDING_INTERRUPT      37055         3.80%         0.16%         5.38us
               CPUID      32718         3.35%         0.08%         3.15us
       EXCEPTION_NMI      23601         2.42%         0.17%         8.87us
                 HLT      15424         1.58%        82.12%      6735.06us
           CR_ACCESS       4089         0.42%         0.02%         6.08us

Total Samples:975981, Total events handled time:126502464.88us.

The default event to be analysed is vmexit, we can use --event to specify it, for example, if we want to trace mmio event:

# ./perf kvm-events report --event mmio
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

         MMIO Access    Samples      Samples%         Time%        Avg time

        0xfee00380:W     196589        64.95%        70.01%         3.83us
        0xfee00310:W      35356        11.68%         6.48%         1.97us
        0xfee00300:W      35356        11.68%        16.37%         4.97us
        0xfee00300:R      35356        11.68%         7.14%         2.17us

Total Samples:302657, Total events handled time:1074746.01us.

We can use --vcpu to specify which vcpu is traced:
root@localhost perf]# ./perf kvm-events report --event mmio --vcpu 1
Warning: Error: expected type 5 but read 4
Warning: Error: expected type 5 but read 0
Warning: unknown op '}'

Analyze events for VCPU 1:

         MMIO Access    Samples      Samples%         Time%        Avg time

        0xfee00380:W      58041        71.20%        74.90%         3.70us
        0xfee00310:W       7826         9.60%         5.28%         1.93us
        0xfee00300:W       7826         9.60%        13.82%         5.06us
        0xfee00300:R       7826         9.60%         6.01%         2.20us

Total Samples:81519, Total events handled time:286577.81us.

And, '--key' is used to sort the result, the possible value sample (default, the result is sorted by samples number), time(the result is sorted by time%):

# ./perf kvm-events report --key time
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Analyze events for all VCPUs:

VM-EXIT Samples Samples% Time% Avg time

HLT 15424 1.58% 82.12% 6735.06us

  EXTERNAL_INTERRUPT     219226        22.46%         8.01%        46.20us
         APIC_ACCESS     438107        44.89%         6.20%        17.91us
      IO_INSTRUCTION     122651        12.57%         1.88%        19.44us
       EPT_VIOLATION      83110         8.52%         1.36%        20.75us
       EXCEPTION_NMI      23601         2.42%         0.17%         8.87us
   PENDING_INTERRUPT      37055         3.80%         0.16%         5.38us
               CPUID      32718         3.35%         0.08%         3.15us
           CR_ACCESS       4089         0.42%         0.02%         6.08us

Total Samples:975981, Total events handled time:126502464.88us.

I hope guys will like it and any comments are welcome! :)

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Quoted 10 lines · Xiao Guangrong

This tool is very like xenoprof(if i remember correctly), and traces kvm events smartly. currently, it supports vmexit/mmio/ioport events.

Usage:
- to trace kvm events:

# ./perf kvm-events record

- show the result

# ./perf kvm-events report

Quoted 5 lines

Some output are as follow:

# ./perf kvm-events report
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'

Integrating the trace-cmd plugins into perf will remedy the above errors:
https://lkml.org/lkml/2011/8/16/352

Unfortunately, that effort is stalled at the moment.

Quoted 16 lines

Analyze events for all VCPUs:

VM-EXIT Samples Samples% Time% Avg time

APIC_ACCESS 438107 44.89% 6.20% 17.91us

  EXTERNAL_INTERRUPT     219226        22.46%         8.01%        46.20us
      IO_INSTRUCTION     122651        12.57%         1.88%        19.44us
       EPT_VIOLATION      83110         8.52%         1.36%        20.75us
   PENDING_INTERRUPT      37055         3.80%         0.16%         5.38us
               CPUID      32718         3.35%         0.08%         3.15us
       EXCEPTION_NMI      23601         2.42%         0.17%         8.87us
                 HLT      15424         1.58%        82.12%      6735.06us
           CR_ACCESS       4089         0.42%         0.02%         6.08us

Quoted 1 line

Total Samples:975981, Total events handled time:126502464.88us.

Have you thought about dumping a time history -- something similar to what perf-script can do with dumping events but adding in kvm-specific analysis like what you are doing in these examples?

Quoted 4 lines

Have you thought about dumping a time history -- something similar to what perf-script can do with dumping events but adding in kvm-specific analysis like what you are doing in these examples?

I will look into it and put it to my todo list if it is possible. Thanks, David!