[Qemu-devel] [PATCH v1 0/3] Fix cputlb flush stats and exporting data

[Qemu-devel] [PATCH v1 0/3] Fix cputlb flush stats and exporting data

[Alex Bennée]

This is mostly just an RFC for discussion as I know a number of GSoC
projects will involve a degree of instrumentation and measurement of
the internals of the TCG.

The first patch just fixes and expands the counters. The second uses
(abuses?) the trace mechanism to export the data via the simpletrace
binary trace format. The final patch is a script that then allows us
to plot the collected data.

So this series raises a few questions/thoughts:

 - doing an atomic_inc(__ATOMIC_SEQ_CST) is inefficient

 It would probably be better to have per-thread counters that are
 summed when needed rather than enforcing sequential consistency on a
 global counter.

 - I could encode the events directly and count them in the script

 This would be more trace-like but we'd loose the counters in the MMI
 which is helpful on a live non-trace-enabled builds if you want to
 get an idea of whats happening.

 - Tracing is very event focused, would it be worth adding some sort
   of counter/sampling support?

 Currently the insertion of the trace_tlb_flushes() event in the entry
 to the run loop is a massive hack. Most of the time the numbers
 haven't changed. I could have just spawned a sampling helper on a
 main-loop timer but I feel this might be a use case thinking about
 for the tracing system.

 - timestamps could be replaced with icount for some analysis

 The icount mechanism would allow for a fairly fine grained matching of
 events to execution time in TCG. Maybe this could be an optional
 replacement?

 - The simpletrace binary format is more efficient than debug output

 One problem I have as a TCG hacker is the normal -d foo output is
 very verbose and generates massive logs. -dfilter was an attempt to
 make that easier but I'm quite happy with the trace approach. A boot
 and build takes only about 85M in trace files compared to the
 gigabytes a text file can take up.

Alex Bennée (3):
  cputlb: fix and enhance TLB statistics
  cpus: dump TLB flush counts as trace event
  new script/analyse-tlb-flushes-simpletrace.py

 cpus.c                                     |  6 +++
 cputlb.c                                   | 27 +++++++++++--
 include/exec/cputlb.h                      |  4 +-
 scripts/analyse-tlb-flushes-simpletrace.py | 62 ++++++++++++++++++++++++++++++
 trace-events                               |  3 ++
 translate-all.c                            |  4 +-
 6 files changed, 101 insertions(+), 5 deletions(-)
 create mode 100755 scripts/analyse-tlb-flushes-simpletrace.py

-- 
2.11.0

[Qemu-devel] [PATCH v1 1/3] cputlb: fix and enhance TLB statistics

[Alex Bennée]

First this fixes the fact that statistics where only being updated if
the build was built with DEBUG_TLB. Also it now counts the flush cases
based on the degree of synchronisation required to run. This is a more
useful discriminator for seeing what is slowing down the translation.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 cputlb.c              | 27 ++++++++++++++++++++++++---
 include/exec/cputlb.h |  4 +++-
 translate-all.c       |  4 +++-
 3 files changed, 30 insertions(+), 5 deletions(-)

diff --git a/cputlb.c b/cputlb.c
index f5d056cc08..224863ed76 100644
--- a/cputlb.c
+++ b/cputlb.c
@@ -92,8 +92,13 @@ static void flush_all_helper(CPUState *src, run_on_cpu_func fn,
     }
 }
 
-/* statistics */
-int tlb_flush_count;
+/* Useful statistics - in rough order of expensiveness to the whole
+ * simulation. Synced flushes are the most expensive as all vCPUs need
+ * to be paused for the flush.
+ */
+int tlb_self_flush_count;        /* from vCPU context */
+int tlb_async_flush_count;       /* Deferred flush */
+int tlb_synced_flush_count;      /* Synced flush, all vCPUs halted */
 
 /* This is OK because CPU architectures generally permit an
  * implementation to drop entries from the TLB at any time, so
@@ -112,7 +117,6 @@ static void tlb_flush_nocheck(CPUState *cpu)
     }
 
     assert_cpu_is_self(cpu);
-    tlb_debug("(count: %d)\n", tlb_flush_count++);
 
     tb_lock();
 
@@ -131,6 +135,7 @@ static void tlb_flush_nocheck(CPUState *cpu)
 
 static void tlb_flush_global_async_work(CPUState *cpu, run_on_cpu_data data)
 {
+    atomic_inc(&tlb_async_flush_count);
     tlb_flush_nocheck(cpu);
 }
 
@@ -143,6 +148,7 @@ void tlb_flush(CPUState *cpu)
                              RUN_ON_CPU_NULL);
         }
     } else {
+        atomic_inc(&tlb_self_flush_count);
         tlb_flush_nocheck(cpu);
     }
 }
@@ -157,6 +163,7 @@ void tlb_flush_all_cpus(CPUState *src_cpu)
 void tlb_flush_all_cpus_synced(CPUState *src_cpu)
 {
     const run_on_cpu_func fn = tlb_flush_global_async_work;
+    atomic_inc(&tlb_synced_flush_count);
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_NULL);
 }
@@ -168,6 +175,7 @@ static void tlb_flush_by_mmuidx_async_work(CPUState *cpu, run_on_cpu_data data)
     int mmu_idx;
 
     assert_cpu_is_self(cpu);
+    atomic_inc(&tlb_async_flush_count);
 
     tb_lock();
 
@@ -206,6 +214,7 @@ void tlb_flush_by_mmuidx(CPUState *cpu, uint16_t idxmap)
                              RUN_ON_CPU_HOST_INT(pending_flushes));
         }
     } else {
+        atomic_inc(&tlb_self_flush_count);
         tlb_flush_by_mmuidx_async_work(cpu,
                                        RUN_ON_CPU_HOST_INT(idxmap));
     }
@@ -219,6 +228,7 @@ void tlb_flush_by_mmuidx_all_cpus(CPUState *src_cpu, uint16_t idxmap)
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
     fn(src_cpu, RUN_ON_CPU_HOST_INT(idxmap));
+    atomic_inc(&tlb_self_flush_count);
 }
 
 void tlb_flush_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
@@ -230,6 +240,7 @@ void tlb_flush_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
+    atomic_inc(&tlb_synced_flush_count);
 }
 
 
@@ -282,6 +293,8 @@ static void tlb_flush_page_async_work(CPUState *cpu, run_on_cpu_data data)
     }
 
     tb_flush_jmp_cache(cpu, addr);
+
+    atomic_inc(&tlb_async_flush_count);
 }
 
 void tlb_flush_page(CPUState *cpu, target_ulong addr)
@@ -293,6 +306,7 @@ void tlb_flush_page(CPUState *cpu, target_ulong addr)
                          RUN_ON_CPU_TARGET_PTR(addr));
     } else {
         tlb_flush_page_async_work(cpu, RUN_ON_CPU_TARGET_PTR(addr));
+        atomic_inc(&tlb_self_flush_count);
     }
 }
 
@@ -329,6 +343,7 @@ static void tlb_flush_page_by_mmuidx_async_work(CPUState *cpu,
     }
 
     tb_flush_jmp_cache(cpu, addr);
+    atomic_inc(&tlb_async_flush_count);
 }
 
 static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
@@ -351,6 +366,7 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
                                        RUN_ON_CPU_HOST_INT(mmu_idx_bitmap));
     } else {
         tlb_flush_page_by_mmuidx_async_work(cpu, data);
+        atomic_inc(&tlb_self_flush_count);
     }
 }
 
@@ -370,6 +386,7 @@ void tlb_flush_page_by_mmuidx(CPUState *cpu, target_ulong addr, uint16_t idxmap)
     } else {
         tlb_check_page_and_flush_by_mmuidx_async_work(
             cpu, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
+        atomic_inc(&tlb_self_flush_count);
     }
 }
 
@@ -387,6 +404,7 @@ void tlb_flush_page_by_mmuidx_all_cpus(CPUState *src_cpu, target_ulong addr,
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     fn(src_cpu, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
+    atomic_inc(&tlb_self_flush_count);
 }
 
 void tlb_flush_page_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
@@ -404,6 +422,7 @@ void tlb_flush_page_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
+    atomic_inc(&tlb_synced_flush_count);
 }
 
 void tlb_flush_page_all_cpus(CPUState *src, target_ulong addr)
@@ -412,6 +431,7 @@ void tlb_flush_page_all_cpus(CPUState *src, target_ulong addr)
 
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     fn(src, RUN_ON_CPU_TARGET_PTR(addr));
+    atomic_inc(&tlb_self_flush_count);
 }
 
 void tlb_flush_page_all_cpus_synced(CPUState *src,
@@ -421,6 +441,7 @@ void tlb_flush_page_all_cpus_synced(CPUState *src,
 
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     async_safe_run_on_cpu(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
+    atomic_inc(&tlb_synced_flush_count);
 }
 
 /* update the TLBs so that writes to code in the virtual page 'addr'
diff --git a/include/exec/cputlb.h b/include/exec/cputlb.h
index 3f941783c5..5085384014 100644
--- a/include/exec/cputlb.h
+++ b/include/exec/cputlb.h
@@ -23,7 +23,9 @@
 /* cputlb.c */
 void tlb_protect_code(ram_addr_t ram_addr);
 void tlb_unprotect_code(ram_addr_t ram_addr);
-extern int tlb_flush_count;
+extern int tlb_self_flush_count;
+extern int tlb_async_flush_count;
+extern int tlb_synced_flush_count;
 
 #endif
 #endif
diff --git a/translate-all.c b/translate-all.c
index b3ee876526..0578ae6123 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -1927,7 +1927,9 @@ void dump_exec_info(FILE *f, fprintf_function cpu_fprintf)
             atomic_read(&tcg_ctx.tb_ctx.tb_flush_count));
     cpu_fprintf(f, "TB invalidate count %d\n",
             tcg_ctx.tb_ctx.tb_phys_invalidate_count);
-    cpu_fprintf(f, "TLB flush count     %d\n", tlb_flush_count);
+    cpu_fprintf(f, "TLB flush counts    self:%d async:%d synced:%d\n",
+                tlb_self_flush_count, tlb_async_flush_count,
+                tlb_synced_flush_count);
     tcg_dump_info(f, cpu_fprintf);
 
     tb_unlock();
-- 
2.11.0

[Qemu-devel] [PATCH v1 2/3] cpus: dump TLB flush counts as trace event

[Alex Bennée]

This can be pre-processed later from the trace file.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 cpus.c       | 6 ++++++
 trace-events | 3 +++
 2 files changed, 9 insertions(+)

diff --git a/cpus.c b/cpus.c
index 740b8dc3f8..fae7344df5 100644
--- a/cpus.c
+++ b/cpus.c
@@ -50,6 +50,8 @@
 #include "qapi-event.h"
 #include "hw/nmi.h"
 #include "sysemu/replay.h"
+#include "exec/cputlb.h"
+#include "trace-root.h"
 
 #ifdef CONFIG_LINUX
 
@@ -1252,6 +1254,10 @@ static int tcg_cpu_exec(CPUState *cpu)
     int64_t ti;
 #endif
 
+    trace_tlb_flush_stats(tlb_self_flush_count,
+                          tlb_async_flush_count,
+                          tlb_synced_flush_count);
+
 #ifdef CONFIG_PROFILER
     ti = profile_getclock();
 #endif
diff --git a/trace-events b/trace-events
index b07a09ba95..fc23e15d25 100644
--- a/trace-events
+++ b/trace-events
@@ -94,6 +94,9 @@ disable exec_tb(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
 disable exec_tb_nocache(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
 disable exec_tb_exit(void *last_tb, unsigned int flags) "tb:%p flags=%x"
 
+# cpus.c
+tlb_flush_stats(int self, int async, int synced) "self:%d async:%d synced:%d"
+
 # translate-all.c
 translate_block(void *tb, uintptr_t pc, uint8_t *tb_code) "tb:%p, pc:0x%"PRIxPTR", tb_code:%p"
 
-- 
2.11.0

[Qemu-devel] [PATCH v1 3/3] new script/analyse-tlb-flushes-simpletrace.py

[Alex Bennée]

This is a simple helper script to extract TLB flush stats from the a
simpletrace file and plot the results.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 scripts/analyse-tlb-flushes-simpletrace.py | 62 ++++++++++++++++++++++++++++++
 1 file changed, 62 insertions(+)
 create mode 100755 scripts/analyse-tlb-flushes-simpletrace.py

diff --git a/scripts/analyse-tlb-flushes-simpletrace.py b/scripts/analyse-tlb-flushes-simpletrace.py
new file mode 100755
index 0000000000..9a1191c154
--- /dev/null
+++ b/scripts/analyse-tlb-flushes-simpletrace.py
@@ -0,0 +1,62 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+#
+# Generate a simple graph of flushes over time
+#
+# Author: Alex Bennée <alex.bennee@linaro.org>
+#
+
+import os
+import simpletrace
+import argparse
+import numpy as np
+import matplotlib.pyplot as plt
+
+class CpuTLBFlushAnalyser(simpletrace.Analyzer):
+    "A simpletrace Analyser for extracting flush stats."
+
+    def __init__(self):
+        self.stats = 0
+        self.timestamps = []
+        self.flush_self = []
+        self.flush_async = []
+        self.flush_synced = []
+
+
+    def tlb_flush_stats(self, timestamp, flush_self, flush_async, flush_synced):
+        "Match for tlb_flush_stats event. Appends counts to the relevant array."
+        self.timestamps.append(timestamp)
+        self.flush_self.append(flush_self)
+        self.flush_async.append(flush_async)
+        self.flush_synced.append(flush_synced)
+        self.stats += 1
+
+
+def get_args():
+    "Grab options"
+    parser = argparse.ArgumentParser()
+    parser.add_argument("--output", "-o", type=str, help="Render plot to file")
+    parser.add_argument("events", type=str, help='trace file read from')
+    parser.add_argument("tracefile", type=str, help='trace file read from')
+    return parser.parse_args()
+
+if __name__ == '__main__':
+    args = get_args()
+
+    # Gather data from the trace
+    analyzer = CpuTLBFlushAnalyser()
+    simpletrace.process(args.events, args.tracefile, analyzer)
+
+#    x = np.arange(analyzer.stats)
+    fself, = plt.plot(analyzer.timestamps, analyzer.flush_self, label="Self")
+    fasync, = plt.plot(analyzer.timestamps, analyzer.flush_async, label="Async")
+    fsynced, = plt.plot(analyzer.timestamps, analyzer.flush_synced, label="Synced")
+
+    plt.legend(handles=[fself, fasync, fsynced])
+    plt.xlabel("Execution Time")
+    plt.ylabel("Culmlative count")
+
+    if args.output:
+        plt.savefig(args.output)
+    else:
+        plt.show()
-- 
2.11.0

Re: [Qemu-devel] [PATCH v1 2/3] cpus: dump TLB flush counts as trace event

[Paolo Bonzini]

On 11/04/2017 18:50, Alex Bennée wrote:
> This can be pre-processed later from the trace file.

What about skipping this patch, and instead adding five trace points

trace_tlb_flush_self(int vcpu)
trace_tlb_flush_async_schedule(int from, int to)
trace_tlb_flush_async_work(int vcpu)
trace_tlb_flush_synced_schedule(int vcpu)
trace_tlb_flush_synced_work(int vcpu)

The disadvantage is that the TLB flush counts are not emitted in "info
tcg", but the resulting information is finer-grained and the offline
accumulation of tracepoints can provide the same information.

Paolo

> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  cpus.c       | 6 ++++++
>  trace-events | 3 +++
>  2 files changed, 9 insertions(+)
> 
> diff --git a/cpus.c b/cpus.c
> index 740b8dc3f8..fae7344df5 100644
> --- a/cpus.c
> +++ b/cpus.c
> @@ -50,6 +50,8 @@
>  #include "qapi-event.h"
>  #include "hw/nmi.h"
>  #include "sysemu/replay.h"
> +#include "exec/cputlb.h"
> +#include "trace-root.h"
>  
>  #ifdef CONFIG_LINUX
>  
> @@ -1252,6 +1254,10 @@ static int tcg_cpu_exec(CPUState *cpu)
>      int64_t ti;
>  #endif
>  
> +    trace_tlb_flush_stats(tlb_self_flush_count,
> +                          tlb_async_flush_count,
> +                          tlb_synced_flush_count);
> +
>  #ifdef CONFIG_PROFILER
>      ti = profile_getclock();
>  #endif
> diff --git a/trace-events b/trace-events
> index b07a09ba95..fc23e15d25 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -94,6 +94,9 @@ disable exec_tb(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
>  disable exec_tb_nocache(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
>  disable exec_tb_exit(void *last_tb, unsigned int flags) "tb:%p flags=%x"
>  
> +# cpus.c
> +tlb_flush_stats(int self, int async, int synced) "self:%d async:%d synced:%d"
> +
>  # translate-all.c
>  translate_block(void *tb, uintptr_t pc, uint8_t *tb_code) "tb:%p, pc:0x%"PRIxPTR", tb_code:%p"
>  
> 

Re: [Qemu-devel] [PATCH v1 2/3] cpus: dump TLB flush counts as trace event

[Alex Bennée]

Paolo Bonzini <pbonzini@redhat.com> writes:

> On 11/04/2017 18:50, Alex Bennée wrote:
>> This can be pre-processed later from the trace file.
>
> What about skipping this patch, and instead adding five trace points
>
> trace_tlb_flush_self(int vcpu)
> trace_tlb_flush_async_schedule(int from, int to)
> trace_tlb_flush_async_work(int vcpu)
> trace_tlb_flush_synced_schedule(int vcpu)
> trace_tlb_flush_synced_work(int vcpu)
>
> The disadvantage is that the TLB flush counts are not emitted in "info
> tcg", but the resulting information is finer-grained and the offline
> accumulation of tracepoints can provide the same information.

In principle I agree. It depends if people find the console based TCG
information useful or not.

I could macro-up something that would use counters when tracing is not
enabled and prompt users to use the tracing interface in the console
when it is.

>
> Paolo
>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  cpus.c       | 6 ++++++
>>  trace-events | 3 +++
>>  2 files changed, 9 insertions(+)
>>
>> diff --git a/cpus.c b/cpus.c
>> index 740b8dc3f8..fae7344df5 100644
>> --- a/cpus.c
>> +++ b/cpus.c
>> @@ -50,6 +50,8 @@
>>  #include "qapi-event.h"
>>  #include "hw/nmi.h"
>>  #include "sysemu/replay.h"
>> +#include "exec/cputlb.h"
>> +#include "trace-root.h"
>>
>>  #ifdef CONFIG_LINUX
>>
>> @@ -1252,6 +1254,10 @@ static int tcg_cpu_exec(CPUState *cpu)
>>      int64_t ti;
>>  #endif
>>
>> +    trace_tlb_flush_stats(tlb_self_flush_count,
>> +                          tlb_async_flush_count,
>> +                          tlb_synced_flush_count);
>> +
>>  #ifdef CONFIG_PROFILER
>>      ti = profile_getclock();
>>  #endif
>> diff --git a/trace-events b/trace-events
>> index b07a09ba95..fc23e15d25 100644
>> --- a/trace-events
>> +++ b/trace-events
>> @@ -94,6 +94,9 @@ disable exec_tb(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
>>  disable exec_tb_nocache(void *tb, uintptr_t pc) "tb:%p pc=0x%"PRIxPTR
>>  disable exec_tb_exit(void *last_tb, unsigned int flags) "tb:%p flags=%x"
>>
>> +# cpus.c
>> +tlb_flush_stats(int self, int async, int synced) "self:%d async:%d synced:%d"
>> +
>>  # translate-all.c
>>  translate_block(void *tb, uintptr_t pc, uint8_t *tb_code) "tb:%p, pc:0x%"PRIxPTR", tb_code:%p"
>>
>>


--
Alex Bennée