[Qemu-devel] [PATCH v2 0/6] gdb updates and cputlb traces

[Qemu-devel] [PATCH v2 0/6] gdb updates and cputlb traces

[Alex Bennée]

Hi,

Here is an update to the cputlb tracing and also a number of gdbstub
updates. The main changes to the cputlb tracing are making each flush
an explicit event instead of just dumping counts. This means you can
so analysis on the delay from queuing work to scheduling at the cost
of losing the raw count in the MMI interface.

Alex Bennée (6):
  scripts/replay-dump.py: replay log dumper
  scripts/qemu-gdb/timers.py: new helper to dump timer state
  scripts/qemu-gdb/tcg: new helper to dump tcg state
  cputlb: remove tlb_flush_count
  cputlb: add trace events
  new script/analyse-tlb-flushes-simpletrace.py

 cputlb.c                                   |  38 +++-
 include/exec/cputlb.h                      |   1 -
 scripts/analyse-tlb-flushes-simpletrace.py | 144 +++++++++++++++
 scripts/qemu-gdb.py                        |   4 +-
 scripts/qemugdb/tcg.py                     |  46 +++++
 scripts/qemugdb/timers.py                  |  54 ++++++
 scripts/replay-dump.py                     | 272 +++++++++++++++++++++++++++++
 trace-events                               |   7 +
 translate-all.c                            |   1 -
 9 files changed, 559 insertions(+), 8 deletions(-)
 create mode 100755 scripts/analyse-tlb-flushes-simpletrace.py
 create mode 100644 scripts/qemugdb/tcg.py
 create mode 100644 scripts/qemugdb/timers.py
 create mode 100755 scripts/replay-dump.py

-- 
2.11.0

[Qemu-devel] [PATCH v2 1/6] scripts/replay-dump.py: replay log dumper

[Alex Bennée]

This script is a debugging tool for looking through the contents of a
replay log file. It is incomplete but should fail gracefully at events
it doesn't understand.

It currently understands two different log formats as the audio
record/replay support was merged during since MTTCG. It was written to
help debug what has caused the BQL changes to break replay support.

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

diff --git a/scripts/replay-dump.py b/scripts/replay-dump.py
new file mode 100755
index 0000000000..fdd178aba0
--- /dev/null
+++ b/scripts/replay-dump.py
@@ -0,0 +1,272 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+#
+# Dump the contents of a recorded execution stream
+#
+#  Copyright (c) 2017 Alex Bennée <alex.bennee@linaro.org>
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library; if not, see <http://www.gnu.org/licenses/>.
+
+import argparse
+import struct
+from collections import namedtuple
+
+# This mirrors some of the global replay state which some of the
+# stream loading refers to. Some decoders may read the next event so
+# we need handle that case. Calling reuse_event will ensure the next
+# event is read from the cache rather than advancing the file.
+
+class ReplayState(object):
+    def __init__(self):
+        self.event = -1
+        self.event_count = 0
+        self.already_read = False
+        self.current_checkpoint = 0
+        self.checkpoint = 0
+
+    def set_event(self, ev):
+        self.event = ev
+        self.event_count += 1
+
+    def get_event(self):
+        self.already_read = False
+        return self.event
+
+    def reuse_event(self, ev):
+        self.event = ev
+        self.already_read = True
+
+    def set_checkpoint(self):
+        self.checkpoint = self.event - self.checkpoint_start
+
+    def get_checkpoint(self):
+        return self.checkpoint
+
+replay_state = ReplayState()
+
+# Simple read functions that mirror replay-internal.c
+# The file-stream is big-endian and manually written out a byte at a time.
+
+def read_byte(fin):
+    "Read a single byte"
+    return struct.unpack('>B', fin.read(1))[0]
+
+def read_event(fin):
+    "Read a single byte event, but save some state"
+    if replay_state.already_read:
+        return replay_state.get_event()
+    else:
+        replay_state.set_event(read_byte(fin))
+        return replay_state.event
+
+def read_word(fin):
+    "Read a 16 bit word"
+    return struct.unpack('>H', fin.read(2))[0]
+
+def read_dword(fin):
+    "Read a 32 bit word"
+    return struct.unpack('>I', fin.read(4))[0]
+
+def read_qword(fin):
+    "Read a 64 bit word"
+    return struct.unpack('>Q', fin.read(8))[0]
+
+# Generic decoder structure
+Decoder = namedtuple("Decoder", "eid name fn")
+
+def call_decode(table, index, dumpfile):
+    "Search decode table for next step"
+    decoder = next((d for d in table if d.eid == index), None)
+    if not decoder:
+        print "Could not decode index: %d" % (index)
+        print "Entry is: %s" % (decoder)
+        print "Decode Table is:\n%s" % (table)
+        return False
+    else:
+        return decoder.fn(decoder.eid, decoder.name, dumpfile)
+
+# Print event
+def print_event(eid, name, string=None, event_count=None):
+    "Print event with count"
+    if not event_count:
+        event_count = replay_state.event_count
+
+    if string:
+        print "%d:%s(%d) %s" % (event_count, name, eid, string)
+    else:
+        print "%d:%s(%d)" % (event_count, name, eid)
+
+
+# Decoders for each event type
+
+def decode_unimp(eid, name, _unused_dumpfile):
+    "Unimplimented decoder, will trigger exit"
+    print "%s not handled - will now stop" % (name)
+    return False
+
+# Checkpoint decoder
+def swallow_async_qword(eid, name, dumpfile):
+    "Swallow a qword of data without looking at it"
+    step_id = read_qword(dumpfile)
+    print "  %s(%d) @ %d" % (name, eid, step_id)
+    return True
+
+async_decode_table = [ Decoder(0, "REPLAY_ASYNC_EVENT_BH", swallow_async_qword),
+                       Decoder(1, "REPLAY_ASYNC_INPUT", decode_unimp),
+                       Decoder(2, "REPLAY_ASYNC_INPUT_SYNC", decode_unimp),
+                       Decoder(3, "REPLAY_ASYNC_CHAR_READ", decode_unimp),
+                       Decoder(4, "REPLAY_ASYNC_EVENT_BLOCK", decode_unimp),
+                       Decoder(5, "REPLAY_ASYNC_EVENT_NET", decode_unimp),
+]
+# See replay_read_events/replay_read_event
+def decode_async(eid, name, dumpfile):
+    """Decode an ASYNC event"""
+
+    print_event(eid, name)
+
+    async_event_kind = read_byte(dumpfile)
+    async_event_checkpoint = read_byte(dumpfile)
+
+    if async_event_checkpoint != replay_state.current_checkpoint:
+        print "  mismatch between checkpoint %d and async data %d" % (
+            replay_state.current_checkpoint, async_event_checkpoint)
+        return True
+
+    return call_decode(async_decode_table, async_event_kind, dumpfile)
+
+
+def decode_instruction(eid, name, dumpfile):
+    ins_diff = read_dword(dumpfile)
+    print_event(eid, name, "0x%x" % (ins_diff))
+    return True
+
+def decode_audio_out(eid, name, dumpfile):
+    audio_data = read_dword(dumpfile)
+    print_event(eid, name, "%d" % (audio_data))
+    return True
+
+def decode_checkpoint(eid, name, dumpfile):
+    """Decode a checkpoint.
+
+    Checkpoints contain a series of async events with their own specific data.
+    """
+    replay_state.set_checkpoint()
+    # save event count as we peek ahead
+    event_number = replay_state.event_count
+    next_event = read_event(dumpfile)
+
+    # if the next event is EVENT_ASYNC there are a bunch of
+    # async events to read, otherwise we are done
+    if next_event != 3:
+        print_event(eid, name, "no additional data", event_number)
+    else:
+        print_event(eid, name, "more data follows", event_number)
+
+    replay_state.reuse_event(next_event)
+    return True
+
+def decode_checkpoint_init(eid, name, dumpfile):
+    print_event(eid, name)
+    return True
+
+def decode_interrupt(eid, name, dumpfile):
+    print_event(eid, name)
+    return True
+
+def decode_clock(eid, name, dumpfile):
+    clock_data = read_qword(dumpfile)
+    print_event(eid, name, "0x%x" % (clock_data))
+    return True
+
+
+# pre-MTTCG merge
+v5_event_table = [Decoder(0, "EVENT_INSTRUCTION", decode_instruction),
+                  Decoder(1, "EVENT_INTERRUPT", decode_interrupt),
+                  Decoder(2, "EVENT_EXCEPTION", decode_unimp),
+                  Decoder(3, "EVENT_ASYNC", decode_async),
+                  Decoder(4, "EVENT_SHUTDOWN", decode_unimp),
+                  Decoder(5, "EVENT_CHAR_WRITE", decode_unimp),
+                  Decoder(6, "EVENT_CHAR_READ_ALL", decode_unimp),
+                  Decoder(7, "EVENT_CHAR_READ_ALL_ERROR", decode_unimp),
+                  Decoder(8, "EVENT_CLOCK_HOST", decode_clock),
+                  Decoder(9, "EVENT_CLOCK_VIRTUAL_RT", decode_clock),
+                  Decoder(10, "EVENT_CP_CLOCK_WARP_START", decode_checkpoint),
+                  Decoder(11, "EVENT_CP_CLOCK_WARP_ACCOUNT", decode_checkpoint),
+                  Decoder(12, "EVENT_CP_RESET_REQUESTED", decode_checkpoint),
+                  Decoder(13, "EVENT_CP_SUSPEND_REQUESTED", decode_checkpoint),
+                  Decoder(14, "EVENT_CP_CLOCK_VIRTUAL", decode_checkpoint),
+                  Decoder(15, "EVENT_CP_CLOCK_HOST", decode_checkpoint),
+                  Decoder(16, "EVENT_CP_CLOCK_VIRTUAL_RT", decode_checkpoint),
+                  Decoder(17, "EVENT_CP_INIT", decode_checkpoint_init),
+                  Decoder(18, "EVENT_CP_RESET", decode_checkpoint),
+]
+
+# post-MTTCG merge, AUDIO support added
+v6_event_table = [Decoder(0, "EVENT_INSTRUCTION", decode_instruction),
+                  Decoder(1, "EVENT_INTERRUPT", decode_interrupt),
+                  Decoder(2, "EVENT_EXCEPTION", decode_unimp),
+                  Decoder(3, "EVENT_ASYNC", decode_async),
+                  Decoder(4, "EVENT_SHUTDOWN", decode_unimp),
+                  Decoder(5, "EVENT_CHAR_WRITE", decode_unimp),
+                  Decoder(6, "EVENT_CHAR_READ_ALL", decode_unimp),
+                  Decoder(7, "EVENT_CHAR_READ_ALL_ERROR", decode_unimp),
+                  Decoder(8, "EVENT_AUDIO_OUT", decode_audio_out),
+                  Decoder(9, "EVENT_AUDIO_IN", decode_unimp),
+                  Decoder(10, "EVENT_CLOCK_HOST", decode_clock),
+                  Decoder(11, "EVENT_CLOCK_VIRTUAL_RT", decode_clock),
+                  Decoder(12, "EVENT_CP_CLOCK_WARP_START", decode_checkpoint),
+                  Decoder(13, "EVENT_CP_CLOCK_WARP_ACCOUNT", decode_checkpoint),
+                  Decoder(14, "EVENT_CP_RESET_REQUESTED", decode_checkpoint),
+                  Decoder(15, "EVENT_CP_SUSPEND_REQUESTED", decode_checkpoint),
+                  Decoder(16, "EVENT_CP_CLOCK_VIRTUAL", decode_checkpoint),
+                  Decoder(17, "EVENT_CP_CLOCK_HOST", decode_checkpoint),
+                  Decoder(18, "EVENT_CP_CLOCK_VIRTUAL_RT", decode_checkpoint),
+                  Decoder(19, "EVENT_CP_INIT", decode_checkpoint_init),
+                  Decoder(20, "EVENT_CP_RESET", decode_checkpoint),
+]
+
+def parse_arguments():
+    "Grab arguments for script"
+    parser = argparse.ArgumentParser()
+    parser.add_argument("-f", "--file", help='record/replay dump to read from',
+                        required=True)
+    return parser.parse_args()
+
+def decode_file(filename):
+    "Decode a record/replay dump"
+    dumpfile = open(filename, "rb")
+
+    # read and throwaway the header
+    version = read_dword(dumpfile)
+    junk = read_qword(dumpfile)
+
+    print "HEADER: version 0x%x" % (version)
+    if version == 0xe02006:
+        event_decode_table = v6_event_table
+        replay_state.checkpoint_start = 12
+    else:
+        event_decode_table = v5_event_table
+        replay_state.checkpoint_start = 10
+
+    try:
+        decode_ok = True
+        while decode_ok:
+            event = read_event(dumpfile)
+            decode_ok = call_decode(event_decode_table, event, dumpfile)
+    finally:
+        dumpfile.close()
+
+if __name__ == "__main__":
+    args = parse_arguments()
+    decode_file(args.file)
-- 
2.11.0

[Qemu-devel] [PATCH v2 2/6] scripts/qemu-gdb/timers.py: new helper to dump timer state

[Alex Bennée]

This introduces the qemu-gdb command "qemu timers" which will dump the
state of the main timers in the system.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
---
 scripts/qemu-gdb.py       |  3 ++-
 scripts/qemugdb/timers.py | 54 +++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 56 insertions(+), 1 deletion(-)
 create mode 100644 scripts/qemugdb/timers.py

diff --git a/scripts/qemu-gdb.py b/scripts/qemu-gdb.py
index b3f8e04f77..3e7adb87dc 100644
--- a/scripts/qemu-gdb.py
+++ b/scripts/qemu-gdb.py
@@ -26,7 +26,7 @@ import os, sys
 
 sys.path.append(os.path.dirname(__file__))
 
-from qemugdb import aio, mtree, coroutine
+from qemugdb import aio, mtree, coroutine, timers
 
 class QemuCommand(gdb.Command):
     '''Prefix for QEMU debug support commands'''
@@ -38,6 +38,7 @@ QemuCommand()
 coroutine.CoroutineCommand()
 mtree.MtreeCommand()
 aio.HandlersCommand()
+timers.TimersCommand()
 
 coroutine.CoroutineSPFunction()
 coroutine.CoroutinePCFunction()
diff --git a/scripts/qemugdb/timers.py b/scripts/qemugdb/timers.py
new file mode 100644
index 0000000000..be71a001e3
--- /dev/null
+++ b/scripts/qemugdb/timers.py
@@ -0,0 +1,54 @@
+#!/usr/bin/python
+# GDB debugging support
+#
+# Copyright 2017 Linaro Ltd
+#
+# Author: Alex Bennée <alex.bennee@linaro.org>
+#
+# This work is licensed under the terms of the GNU GPL, version 2.  See
+# the COPYING file in the top-level directory.
+
+# 'qemu timers' -- display the current timerlists
+
+import gdb
+
+class TimersCommand(gdb.Command):
+    '''Display the current QEMU timers'''
+
+    def __init__(self):
+        'Register the class as a gdb command'
+        gdb.Command.__init__(self, 'qemu timers', gdb.COMMAND_DATA,
+                             gdb.COMPLETE_NONE)
+
+    def dump_timers(self, timer):
+        "Follow a timer and recursively dump each one in the list."
+        # timer should be of type QemuTimer
+        gdb.write("    timer %s/%s (cb:%s,opq:%s)\n" % (
+            timer['expire_time'],
+            timer['scale'],
+            timer['cb'],
+            timer['opaque']))
+
+        if int(timer['next']) > 0:
+            self.dump_timers(timer['next'])
+
+
+    def process_timerlist(self, tlist, ttype):
+        gdb.write("Processing %s timers\n" % (ttype))
+        gdb.write("  clock %s is enabled:%s, last:%s\n" % (
+            tlist['clock']['type'],
+            tlist['clock']['enabled'],
+            tlist['clock']['last']))
+        if int(tlist['active_timers']) > 0:
+            self.dump_timers(tlist['active_timers'])
+
+
+    def invoke(self, arg, from_tty):
+        'Run the command'
+        main_timers = gdb.parse_and_eval("main_loop_tlg")
+
+        # This will break if QEMUClockType in timer.h is redfined
+        self.process_timerlist(main_timers['tl'][0], "Realtime")
+        self.process_timerlist(main_timers['tl'][1], "Virtual")
+        self.process_timerlist(main_timers['tl'][2], "Host")
+        self.process_timerlist(main_timers['tl'][3], "Virtual RT")
-- 
2.11.0

[Qemu-devel] [PATCH v2 3/6] scripts/qemu-gdb/tcg: new helper to dump tcg state

[Alex Bennée]

This adds a simple helper to dump lock state within TCG.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 scripts/qemu-gdb.py    |  3 ++-
 scripts/qemugdb/tcg.py | 46 ++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 48 insertions(+), 1 deletion(-)
 create mode 100644 scripts/qemugdb/tcg.py

diff --git a/scripts/qemu-gdb.py b/scripts/qemu-gdb.py
index 3e7adb87dc..91e928f6af 100644
--- a/scripts/qemu-gdb.py
+++ b/scripts/qemu-gdb.py
@@ -26,7 +26,7 @@ import os, sys
 
 sys.path.append(os.path.dirname(__file__))
 
-from qemugdb import aio, mtree, coroutine, timers
+from qemugdb import aio, mtree, coroutine, timers, tcg
 
 class QemuCommand(gdb.Command):
     '''Prefix for QEMU debug support commands'''
@@ -39,6 +39,7 @@ coroutine.CoroutineCommand()
 mtree.MtreeCommand()
 aio.HandlersCommand()
 timers.TimersCommand()
+tcg.TCGLockStatusCommand()
 
 coroutine.CoroutineSPFunction()
 coroutine.CoroutinePCFunction()
diff --git a/scripts/qemugdb/tcg.py b/scripts/qemugdb/tcg.py
new file mode 100644
index 0000000000..8c7f1d7454
--- /dev/null
+++ b/scripts/qemugdb/tcg.py
@@ -0,0 +1,46 @@
+#!/usr/bin/python
+# -*- coding: utf-8 -*-
+#
+# GDB debugging support, TCG status
+#
+# Copyright 2016 Linaro Ltd
+#
+# Authors:
+#  Alex Bennée <alex.bennee@linaro.org>
+#
+# This work is licensed under the terms of the GNU GPL, version 2.  See
+# the COPYING file in the top-level directory.
+#
+# Contributions after 2012-01-13 are licensed under the terms of the
+# GNU GPL, version 2 or (at your option) any later version.
+
+# 'qemu tcg-lock-status' -- display the TCG lock status across threads
+
+import gdb
+
+class TCGLockStatusCommand(gdb.Command):
+    '''Display TCG Execution Status'''
+    def __init__(self):
+        gdb.Command.__init__(self, 'qemu tcg-lock-status', gdb.COMMAND_DATA,
+                             gdb.COMPLETE_NONE)
+
+    def invoke(self, arg, from_tty):
+        gdb.write("Thread, BQL (iothread_mutex), Replay, Blocked?\n")
+        for thread in gdb.inferiors()[0].threads():
+            thread.switch()
+
+            iothread = gdb.parse_and_eval("iothread_locked")
+            replay = gdb.parse_and_eval("replay_locked")
+
+            frame = gdb.selected_frame()
+            if frame.name() == "__lll_lock_wait":
+                frame.older().select()
+                mutex = gdb.parse_and_eval("mutex")
+                owner = gdb.parse_and_eval("mutex->__data.__owner")
+                blocked = ("__lll_lock_wait waiting on %s from %d" %
+                           (mutex, owner))
+            else:
+                blocked = "not blocked"
+
+            gdb.write("%d/%d, %s, %s, %s\n" % (thread.num, thread.ptid[1],
+                                               iothread, replay, blocked))
-- 
2.11.0

[Qemu-devel] [PATCH v2 4/6] cputlb: remove tlb_flush_count

[Alex Bennée]

Flushing of the CPU TLB is no longer a simple count. The ratio of
self-flushes to cross-flushes and if they need to synchronise across
vCPUs has more of an impact. To correctly capture this we'll replace
the simple count with trace points in a future patch.

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

diff --git a/cputlb.c b/cputlb.c
index f5d056cc08..d1859c3f37 100644
--- a/cputlb.c
+++ b/cputlb.c
@@ -92,9 +92,6 @@ static void flush_all_helper(CPUState *src, run_on_cpu_func fn,
     }
 }
 
-/* statistics */
-int tlb_flush_count;
-
 /* This is OK because CPU architectures generally permit an
  * implementation to drop entries from the TLB at any time, so
  * flushing more entries than required is only an efficiency issue,
@@ -112,7 +109,6 @@ static void tlb_flush_nocheck(CPUState *cpu)
     }
 
     assert_cpu_is_self(cpu);
-    tlb_debug("(count: %d)\n", tlb_flush_count++);
 
     tb_lock();
 
diff --git a/include/exec/cputlb.h b/include/exec/cputlb.h
index 3f941783c5..dac9901da5 100644
--- a/include/exec/cputlb.h
+++ b/include/exec/cputlb.h
@@ -23,7 +23,6 @@
 /* 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;
 
 #endif
 #endif
diff --git a/translate-all.c b/translate-all.c
index b3ee876526..eeb3807242 100644
--- a/translate-all.c
+++ b/translate-all.c
@@ -1927,7 +1927,6 @@ 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);
     tcg_dump_info(f, cpu_fprintf);
 
     tb_unlock();
-- 
2.11.0

[Qemu-devel] [PATCH v2 5/6] cputlb: add trace events

[Alex Bennée]

Given the range of costs for various SoftMMU TLB operations from
deferring work for the currently running vCPU to bring the whole
emulated machine to a stop for synchronised updates simple counters
are less useful. Instead we log events via the trace infrastructure
and we can then post-process the data in a range of ways.

  tlb_flush_self - the vCPU flushed its own TLB
  tlb_flush_async_schedule - work was scheduled and the vCPU kicked
  tlb_flush_synced_schedule - exclusive work was scheduled on a vCPU
  tlb_flush_work - scheduled work was done

We can use the difference between the work being scheduled and
tlb_flush_work to calculate the latency introduced.

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 cputlb.c     | 34 +++++++++++++++++++++++++++++++++-
 trace-events |  7 +++++++
 2 files changed, 40 insertions(+), 1 deletion(-)

diff --git a/cputlb.c b/cputlb.c
index d1859c3f37..b2490863e4 100644
--- a/cputlb.c
+++ b/cputlb.c
@@ -127,6 +127,7 @@ static void tlb_flush_nocheck(CPUState *cpu)
 
 static void tlb_flush_global_async_work(CPUState *cpu, run_on_cpu_data data)
 {
+    trace_tlb_flush_work(__func__, cpu->cpu_index);
     tlb_flush_nocheck(cpu);
 }
 
@@ -135,17 +136,22 @@ void tlb_flush(CPUState *cpu)
     if (cpu->created && !qemu_cpu_is_self(cpu)) {
         if (atomic_mb_read(&cpu->pending_tlb_flush) != ALL_MMUIDX_BITS) {
             atomic_mb_set(&cpu->pending_tlb_flush, ALL_MMUIDX_BITS);
+            trace_tlb_flush_async_schedule(__func__, current_cpu ?
+                                           current_cpu->cpu_index :
+                                           cpu->cpu_index, cpu->cpu_index);
             async_run_on_cpu(cpu, tlb_flush_global_async_work,
                              RUN_ON_CPU_NULL);
         }
     } else {
-        tlb_flush_nocheck(cpu);
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
+        tlb_flush_global_async_work(cpu, RUN_ON_CPU_NULL);
     }
 }
 
 void tlb_flush_all_cpus(CPUState *src_cpu)
 {
     const run_on_cpu_func fn = tlb_flush_global_async_work;
+    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
     fn(src_cpu, RUN_ON_CPU_NULL);
 }
@@ -153,6 +159,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;
+    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
     async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_NULL);
 }
@@ -163,6 +170,8 @@ static void tlb_flush_by_mmuidx_async_work(CPUState *cpu, run_on_cpu_data data)
     unsigned long mmu_idx_bitmask = data.host_int;
     int mmu_idx;
 
+    trace_tlb_flush_work(__func__, cpu->cpu_index);
+
     assert_cpu_is_self(cpu);
 
     tb_lock();
@@ -196,12 +205,16 @@ void tlb_flush_by_mmuidx(CPUState *cpu, uint16_t idxmap)
 
         if (pending_flushes) {
             tlb_debug("reduced mmu_idx: 0x%" PRIx16 "\n", pending_flushes);
+            trace_tlb_flush_async_schedule(__func__,
+                                           current_cpu->cpu_index,
+                                           cpu->cpu_index);
 
             atomic_or(&cpu->pending_tlb_flush, pending_flushes);
             async_run_on_cpu(cpu, tlb_flush_by_mmuidx_async_work,
                              RUN_ON_CPU_HOST_INT(pending_flushes));
         }
     } else {
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
         tlb_flush_by_mmuidx_async_work(cpu,
                                        RUN_ON_CPU_HOST_INT(idxmap));
     }
@@ -212,6 +225,7 @@ void tlb_flush_by_mmuidx_all_cpus(CPUState *src_cpu, uint16_t idxmap)
     const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
 
     tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
+    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
 
     flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
     fn(src_cpu, RUN_ON_CPU_HOST_INT(idxmap));
@@ -223,6 +237,7 @@ void tlb_flush_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
     const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
 
     tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
+    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
 
     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));
@@ -252,6 +267,7 @@ static void tlb_flush_page_async_work(CPUState *cpu, run_on_cpu_data data)
     assert_cpu_is_self(cpu);
 
     tlb_debug("page :" TARGET_FMT_lx "\n", addr);
+    trace_tlb_flush_work(__func__, cpu->cpu_index);
 
     /* Check if we need to flush due to large pages.  */
     if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
@@ -285,9 +301,12 @@ void tlb_flush_page(CPUState *cpu, target_ulong addr)
     tlb_debug("page :" TARGET_FMT_lx "\n", addr);
 
     if (!qemu_cpu_is_self(cpu)) {
+        trace_tlb_flush_async_schedule(__func__, current_cpu->cpu_index,
+                                       cpu->cpu_index);
         async_run_on_cpu(cpu, tlb_flush_page_async_work,
                          RUN_ON_CPU_TARGET_PTR(addr));
     } else {
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
         tlb_flush_page_async_work(cpu, RUN_ON_CPU_TARGET_PTR(addr));
     }
 }
@@ -312,6 +331,7 @@ static void tlb_flush_page_by_mmuidx_async_work(CPUState *cpu,
 
     tlb_debug("page:%d addr:"TARGET_FMT_lx" mmu_idx:0x%lx\n",
               page, addr, mmu_idx_bitmap);
+    trace_tlb_flush_work(__func__, cpu->cpu_index);
 
     for (mmu_idx = 0; mmu_idx < NB_MMU_MODES; mmu_idx++) {
         if (test_bit(mmu_idx, &mmu_idx_bitmap)) {
@@ -336,6 +356,7 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
     unsigned long mmu_idx_bitmap = addr_and_mmuidx & ALL_MMUIDX_BITS;
 
     tlb_debug("addr:"TARGET_FMT_lx" mmu_idx: %04lx\n", addr, mmu_idx_bitmap);
+    trace_tlb_flush_work(__func__, cpu->cpu_index);
 
     /* Check if we need to flush due to large pages.  */
     if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
@@ -343,9 +364,11 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
                   TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
                   env->tlb_flush_addr, env->tlb_flush_mask);
 
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
         tlb_flush_by_mmuidx_async_work(cpu,
                                        RUN_ON_CPU_HOST_INT(mmu_idx_bitmap));
     } else {
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
         tlb_flush_page_by_mmuidx_async_work(cpu, data);
     }
 }
@@ -361,9 +384,12 @@ void tlb_flush_page_by_mmuidx(CPUState *cpu, target_ulong addr, uint16_t idxmap)
     addr_and_mmu_idx |= idxmap;
 
     if (!qemu_cpu_is_self(cpu)) {
+        trace_tlb_flush_async_schedule(__func__, current_cpu->cpu_index,
+                                       cpu->cpu_index);
         async_run_on_cpu(cpu, tlb_check_page_and_flush_by_mmuidx_async_work,
                          RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     } else {
+        trace_tlb_flush_self(__func__, cpu->cpu_index);
         tlb_check_page_and_flush_by_mmuidx_async_work(
             cpu, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
     }
@@ -376,6 +402,7 @@ void tlb_flush_page_by_mmuidx_all_cpus(CPUState *src_cpu, target_ulong addr,
     target_ulong addr_and_mmu_idx;
 
     tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
+    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
 
     /* This should already be page aligned */
     addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
@@ -393,6 +420,7 @@ void tlb_flush_page_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
     target_ulong addr_and_mmu_idx;
 
     tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
+    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
 
     /* This should already be page aligned */
     addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
@@ -406,6 +434,8 @@ void tlb_flush_page_all_cpus(CPUState *src, target_ulong addr)
 {
     const run_on_cpu_func fn = tlb_flush_page_async_work;
 
+    trace_tlb_flush_async_schedule(__func__, src->cpu_index, -1);
+
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     fn(src, RUN_ON_CPU_TARGET_PTR(addr));
 }
@@ -415,6 +445,8 @@ void tlb_flush_page_all_cpus_synced(CPUState *src,
 {
     const run_on_cpu_func fn = tlb_flush_page_async_work;
 
+    trace_tlb_flush_synced_schedule(__func__, src->cpu_index, -1);
+
     flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
     async_safe_run_on_cpu(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
 }
diff --git a/trace-events b/trace-events
index e582d6315d..500f84b8c4 100644
--- a/trace-events
+++ b/trace-events
@@ -78,6 +78,13 @@ 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"
 
+# SoftMMU TLB flushes
+#   - setting to=-1 indicates work scheduled on all vCPUs
+tlb_flush_self(const char *fn, int vcpu) "%s: cpu %d"
+tlb_flush_async_schedule(const char *fn, int from, int to) "%s: from_cpu=%d to_cpu=%d"
+tlb_flush_synced_schedule(const char *fn, int from, int to) "%s: from_cpu=%d to_cpu=%d"
+tlb_flush_work(const char *fn, int vcpu) "%s: cpu %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 v2 6/6] 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>

---
v2
  - re-factored for new trace events
  - added time and latency graphs
---
 scripts/analyse-tlb-flushes-simpletrace.py | 144 +++++++++++++++++++++++++++++
 1 file changed, 144 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..03fab8c86b
--- /dev/null
+++ b/scripts/analyse-tlb-flushes-simpletrace.py
@@ -0,0 +1,144 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+#
+# Generate a simple graph of flushes over time
+#
+# Author: Alex Bennée <alex.bennee@linaro.org>
+#
+# analyzer = CpuTLBFlushAnalyser(4)
+# simpletrace.process("../trace-events-all", "../trace-22464", analyzer)
+
+import os
+import simpletrace
+import argparse
+import numpy as np
+import matplotlib
+# Force matplotlib to not use any Xwindows backend.
+matplotlib.use('Agg')
+import matplotlib.pyplot as plt
+
+class FlushType:
+    Self, Async, Synced = range(3)
+
+class CpuTLBFlushAnalyser(simpletrace.Analyzer):
+    "A simpletrace Analyser for extracting flush stats."
+
+    def __init__(self, nvcpus):
+        self.flush_total = 0
+        self.flush_all = 0
+        self.nvcpus = nvcpus
+        self.vcpu_last = [[] for _ in range(nvcpus)]
+        self.flush_self = []
+        self.flush_self_times = []
+        self.flush_async = []
+        self.flush_async_times = []
+        self.flush_synced = []
+        self.flush_synced_times = []
+        self.flush_work = []
+
+        self.unmatched_work = []
+
+    def __save_queue(self, vcpu, record):
+        self.flush_total += 1
+        # FIXME: don't seem to see -1
+        if vcpu > 0x7fffffff:
+            self.flush_all += 1
+            for i in range(0, self.nvcpus):
+                self.vcpu_last[i].append(record)
+        else:
+            self.vcpu_last[vcpu].append(record)
+
+    def tlb_flush_self(self, timestamp, fn, vcpu):
+        self.__save_queue(vcpu, (timestamp[0], FlushType.Self))
+        self.flush_self.append((timestamp[0], vcpu))
+
+    def tlb_flush_async_schedule(self, timestamp, fn, from_vcpu, to_vcpu):
+        self.__save_queue(to_vcpu, (timestamp[0], FlushType.Async,
+                                    to_vcpu, from_vcpu))
+        self.flush_async.append((timestamp[0], to_vcpu))
+
+    def tlb_flush_synced_schedule(self, timestamp, fn, from_vcpu, to_vcpu):
+        self.__save_queue(to_vcpu, (timestamp[0], FlushType.Synced,
+                                    to_vcpu, from_vcpu))
+        self.flush_synced.append((timestamp[0], to_vcpu))
+
+    def tlb_flush_work(self, timestamp, fn, vcpu):
+        "Check when it was queued and work out how long it took"
+
+        if len(self.vcpu_last[vcpu]):
+            last = self.vcpu_last[vcpu].pop(0)
+            latency = timestamp[0] - last[0]
+            switcher = {
+                FlushType.Self: lambda a: a.flush_self_times.append(latency),
+                FlushType.Async: lambda a: a.flush_async_times.append(latency),
+                FlushType.Synced: lambda a: a.flush_synced_times.append(latency),
+            }
+            switcher.get(last[1])(self)
+
+            self.flush_work.append((timestamp[0], vcpu))
+        else:
+            self.unmatched_work.append((timestamp[0], vcpu, fn))
+
+
+
+
+def get_args():
+    "Grab options"
+    parser = argparse.ArgumentParser()
+    parser.add_argument("--output", "-o", type=str, help="Render plot to file")
+    parser.add_argument("--vcpus", type=int, help="Number of vCPUS")
+    parser.add_argument("--graph", choices=['time', 'latency'], default='time')
+    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()
+
+def plot_time_series(time_data, label):
+    "Plot one timeseries, return star and end time limits"
+    counts = np.arange(0, len(time_data))
+    times = [x[0] for x in time_data]
+    plt.plot(times, counts, label=label)
+    return (times[0],times[-1])
+
+
+if __name__ == '__main__':
+    args = get_args()
+
+    # Gather data from the trace
+    analyzer = CpuTLBFlushAnalyser(args.vcpus)
+
+    simpletrace.process(args.events, args.tracefile, analyzer)
+
+    # Print some summary stats
+    print ("Flushes: self:%d async:%d synced:%d" %
+           ( len(analyzer.flush_self),
+             len(analyzer.flush_async),
+             len(analyzer.flush_synced)))
+
+    if args.graph == 'time':
+        start_self, end_self = plot_time_series(analyzer.flush_self, "Self")
+        start_async, end_async = plot_time_series(analyzer.flush_async, "Async")
+        start_synced, end_synced = plot_time_series(analyzer.flush_synced, "Self")
+
+        # start right at the edge
+        plt.xlim(xmin=min(start_self, start_async, start_synced))
+    elif args.graph == 'latency':
+
+        # Three subplots, the axes array is 1-d
+
+        f, (ax_self, ax_async, ax_synced) = plt.subplots(3, sharex=True)
+        ax_self.set_title("Distribution")
+
+        ax_self.hist(analyzer.flush_self_times, 10, normed=1,
+                     facecolor='green', alpha=0.5)
+        ax_self.hist(analyzer.flush_async_times, 10, normed=1,
+                     facecolor='blue', alpha=0.5)
+        ax_self.hist(analyzer.flush_synced_times,
+                     10, normed=1,
+                     facecolor='red', alpha=0.5)
+    else:
+        raise ValueError("Bad graph type")
+
+    if args.output:
+        plt.savefig(args.output)
+    else:
+        plt.show()
-- 
2.11.0

Re: [Qemu-devel] [PATCH v2 0/6] gdb updates and cputlb traces

[Stefan Hajnoczi]

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

On Wed, May 17, 2017 at 03:52:53PM +0100, Alex Bennée wrote:
> Hi,
> 
> Here is an update to the cputlb tracing and also a number of gdbstub
> updates. The main changes to the cputlb tracing are making each flush
> an explicit event instead of just dumping counts. This means you can
> so analysis on the delay from queuing work to scheduling at the cost
> of losing the raw count in the MMI interface.
> 
> Alex Bennée (6):
>   scripts/replay-dump.py: replay log dumper
>   scripts/qemu-gdb/timers.py: new helper to dump timer state
>   scripts/qemu-gdb/tcg: new helper to dump tcg state
>   cputlb: remove tlb_flush_count
>   cputlb: add trace events
>   new script/analyse-tlb-flushes-simpletrace.py
> 
>  cputlb.c                                   |  38 +++-
>  include/exec/cputlb.h                      |   1 -
>  scripts/analyse-tlb-flushes-simpletrace.py | 144 +++++++++++++++
>  scripts/qemu-gdb.py                        |   4 +-
>  scripts/qemugdb/tcg.py                     |  46 +++++
>  scripts/qemugdb/timers.py                  |  54 ++++++
>  scripts/replay-dump.py                     | 272 +++++++++++++++++++++++++++++
>  trace-events                               |   7 +
>  translate-all.c                            |   1 -
>  9 files changed, 559 insertions(+), 8 deletions(-)
>  create mode 100755 scripts/analyse-tlb-flushes-simpletrace.py
>  create mode 100644 scripts/qemugdb/tcg.py
>  create mode 100644 scripts/qemugdb/timers.py
>  create mode 100755 scripts/replay-dump.py
> 
> -- 
> 2.11.0
> 

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: [Qemu-devel] [PATCH v2 6/6] new script/analyse-tlb-flushes-simpletrace.py

[Pranith Kumar]

Hi Alex,

Please find some comments and questions below:

On Wed, May 17, 2017 at 10:52 AM, Alex Bennée <alex.bennee@linaro.org> wrote:
> 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>
>
> ---
> v2
>   - re-factored for new trace events
>   - added time and latency graphs
> ---
>  scripts/analyse-tlb-flushes-simpletrace.py | 144 +++++++++++++++++++++++++++++
>  1 file changed, 144 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..03fab8c86b
> --- /dev/null
> +++ b/scripts/analyse-tlb-flushes-simpletrace.py

<snip>

> +
> +def get_args():
> +    "Grab options"
> +    parser = argparse.ArgumentParser()
> +    parser.add_argument("--output", "-o", type=str, help="Render plot to file")
> +    parser.add_argument("--vcpus", type=int, help="Number of vCPUS")

It is not really clear what this argument is for. I guess you are
saying how many cpus the guest from which trace file was generated
had? What happens if we pass in less number of vcpus than used for
generation?

> +    parser.add_argument("--graph", choices=['time', 'latency'], default='time')

What does latency here indicate? I tried this argument on a sample
trace file I generated, and it had three empty boxes.

> +    parser.add_argument("events", type=str, help='trace file read from')
> +    parser.add_argument("tracefile", type=str, help='trace file read from')

The help text for 'events' file here should be something like 'the
trace events file'.

Thanks,
--
Pranith

Re: [Qemu-devel] [PATCH v2 3/6] scripts/qemu-gdb/tcg: new helper to dump tcg state

[Philippe Mathieu-Daudé]

On 05/17/2017 11:52 AM, Alex Bennée wrote:
> This adds a simple helper to dump lock state within TCG.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  scripts/qemu-gdb.py    |  3 ++-
>  scripts/qemugdb/tcg.py | 46 ++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 48 insertions(+), 1 deletion(-)
>  create mode 100644 scripts/qemugdb/tcg.py
>
> diff --git a/scripts/qemu-gdb.py b/scripts/qemu-gdb.py
> index 3e7adb87dc..91e928f6af 100644
> --- a/scripts/qemu-gdb.py
> +++ b/scripts/qemu-gdb.py
> @@ -26,7 +26,7 @@ import os, sys
>
>  sys.path.append(os.path.dirname(__file__))
>
> -from qemugdb import aio, mtree, coroutine, timers
> +from qemugdb import aio, mtree, coroutine, timers, tcg
>
>  class QemuCommand(gdb.Command):
>      '''Prefix for QEMU debug support commands'''
> @@ -39,6 +39,7 @@ coroutine.CoroutineCommand()
>  mtree.MtreeCommand()
>  aio.HandlersCommand()
>  timers.TimersCommand()
> +tcg.TCGLockStatusCommand()
>
>  coroutine.CoroutineSPFunction()
>  coroutine.CoroutinePCFunction()
> diff --git a/scripts/qemugdb/tcg.py b/scripts/qemugdb/tcg.py
> new file mode 100644
> index 0000000000..8c7f1d7454
> --- /dev/null
> +++ b/scripts/qemugdb/tcg.py
> @@ -0,0 +1,46 @@
> +#!/usr/bin/python
> +# -*- coding: utf-8 -*-
> +#
> +# GDB debugging support, TCG status
> +#
> +# Copyright 2016 Linaro Ltd
> +#
> +# Authors:
> +#  Alex Bennée <alex.bennee@linaro.org>
> +#
> +# This work is licensed under the terms of the GNU GPL, version 2.  See
> +# the COPYING file in the top-level directory.
> +#
> +# Contributions after 2012-01-13 are licensed under the terms of the
> +# GNU GPL, version 2 or (at your option) any later version.
> +
> +# 'qemu tcg-lock-status' -- display the TCG lock status across threads
> +
> +import gdb
> +
> +class TCGLockStatusCommand(gdb.Command):
> +    '''Display TCG Execution Status'''
> +    def __init__(self):
> +        gdb.Command.__init__(self, 'qemu tcg-lock-status', gdb.COMMAND_DATA,
> +                             gdb.COMPLETE_NONE)
> +
> +    def invoke(self, arg, from_tty):
> +        gdb.write("Thread, BQL (iothread_mutex), Replay, Blocked?\n")
> +        for thread in gdb.inferiors()[0].threads():
> +            thread.switch()
> +
> +            iothread = gdb.parse_and_eval("iothread_locked")
> +            replay = gdb.parse_and_eval("replay_locked")
> +
> +            frame = gdb.selected_frame()
> +            if frame.name() == "__lll_lock_wait":
> +                frame.older().select()
> +                mutex = gdb.parse_and_eval("mutex")
> +                owner = gdb.parse_and_eval("mutex->__data.__owner")
> +                blocked = ("__lll_lock_wait waiting on %s from %d" %
> +                           (mutex, owner))
> +            else:
> +                blocked = "not blocked"
> +
> +            gdb.write("%d/%d, %s, %s, %s\n" % (thread.num, thread.ptid[1],
> +                                               iothread, replay, blocked))
>

Re: [Qemu-devel] [PATCH v2 1/6] scripts/replay-dump.py: replay log dumper

[Philippe Mathieu-Daudé]

On 05/17/2017 11:52 AM, Alex Bennée wrote:
> This script is a debugging tool for looking through the contents of a
> replay log file. It is incomplete but should fail gracefully at events
> it doesn't understand.
>
> It currently understands two different log formats as the audio
> record/replay support was merged during since MTTCG. It was written to
> help debug what has caused the BQL changes to break replay support.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>  scripts/replay-dump.py | 272 +++++++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 272 insertions(+)
>  create mode 100755 scripts/replay-dump.py
>
> diff --git a/scripts/replay-dump.py b/scripts/replay-dump.py
> new file mode 100755
> index 0000000000..fdd178aba0
> --- /dev/null
> +++ b/scripts/replay-dump.py
> @@ -0,0 +1,272 @@
> +#!/usr/bin/env python
> +# -*- coding: utf-8 -*-
> +#
> +# Dump the contents of a recorded execution stream
> +#
> +#  Copyright (c) 2017 Alex Bennée <alex.bennee@linaro.org>
> +#
> +# This library is free software; you can redistribute it and/or
> +# modify it under the terms of the GNU Lesser General Public
> +# License as published by the Free Software Foundation; either
> +# version 2 of the License, or (at your option) any later version.
> +#
> +# This library is distributed in the hope that it will be useful,
> +# but WITHOUT ANY WARRANTY; without even the implied warranty of
> +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
> +# Lesser General Public License for more details.
> +#
> +# You should have received a copy of the GNU Lesser General Public
> +# License along with this library; if not, see <http://www.gnu.org/licenses/>.
> +
> +import argparse
> +import struct
> +from collections import namedtuple
> +
> +# This mirrors some of the global replay state which some of the
> +# stream loading refers to. Some decoders may read the next event so
> +# we need handle that case. Calling reuse_event will ensure the next
> +# event is read from the cache rather than advancing the file.
> +
> +class ReplayState(object):
> +    def __init__(self):
> +        self.event = -1
> +        self.event_count = 0
> +        self.already_read = False
> +        self.current_checkpoint = 0
> +        self.checkpoint = 0
> +
> +    def set_event(self, ev):
> +        self.event = ev
> +        self.event_count += 1
> +
> +    def get_event(self):
> +        self.already_read = False
> +        return self.event
> +
> +    def reuse_event(self, ev):
> +        self.event = ev
> +        self.already_read = True
> +
> +    def set_checkpoint(self):
> +        self.checkpoint = self.event - self.checkpoint_start
> +
> +    def get_checkpoint(self):
> +        return self.checkpoint
> +
> +replay_state = ReplayState()
> +
> +# Simple read functions that mirror replay-internal.c
> +# The file-stream is big-endian and manually written out a byte at a time.
> +
> +def read_byte(fin):
> +    "Read a single byte"
> +    return struct.unpack('>B', fin.read(1))[0]
> +
> +def read_event(fin):
> +    "Read a single byte event, but save some state"
> +    if replay_state.already_read:
> +        return replay_state.get_event()
> +    else:
> +        replay_state.set_event(read_byte(fin))
> +        return replay_state.event
> +
> +def read_word(fin):
> +    "Read a 16 bit word"
> +    return struct.unpack('>H', fin.read(2))[0]
> +
> +def read_dword(fin):
> +    "Read a 32 bit word"
> +    return struct.unpack('>I', fin.read(4))[0]
> +
> +def read_qword(fin):
> +    "Read a 64 bit word"
> +    return struct.unpack('>Q', fin.read(8))[0]
> +
> +# Generic decoder structure
> +Decoder = namedtuple("Decoder", "eid name fn")
> +
> +def call_decode(table, index, dumpfile):
> +    "Search decode table for next step"
> +    decoder = next((d for d in table if d.eid == index), None)
> +    if not decoder:
> +        print "Could not decode index: %d" % (index)
> +        print "Entry is: %s" % (decoder)
> +        print "Decode Table is:\n%s" % (table)
> +        return False
> +    else:
> +        return decoder.fn(decoder.eid, decoder.name, dumpfile)
> +
> +# Print event
> +def print_event(eid, name, string=None, event_count=None):
> +    "Print event with count"
> +    if not event_count:
> +        event_count = replay_state.event_count
> +
> +    if string:
> +        print "%d:%s(%d) %s" % (event_count, name, eid, string)
> +    else:
> +        print "%d:%s(%d)" % (event_count, name, eid)
> +
> +
> +# Decoders for each event type
> +
> +def decode_unimp(eid, name, _unused_dumpfile):
> +    "Unimplimented decoder, will trigger exit"
> +    print "%s not handled - will now stop" % (name)
> +    return False
> +
> +# Checkpoint decoder
> +def swallow_async_qword(eid, name, dumpfile):
> +    "Swallow a qword of data without looking at it"
> +    step_id = read_qword(dumpfile)
> +    print "  %s(%d) @ %d" % (name, eid, step_id)
> +    return True
> +
> +async_decode_table = [ Decoder(0, "REPLAY_ASYNC_EVENT_BH", swallow_async_qword),
> +                       Decoder(1, "REPLAY_ASYNC_INPUT", decode_unimp),
> +                       Decoder(2, "REPLAY_ASYNC_INPUT_SYNC", decode_unimp),
> +                       Decoder(3, "REPLAY_ASYNC_CHAR_READ", decode_unimp),
> +                       Decoder(4, "REPLAY_ASYNC_EVENT_BLOCK", decode_unimp),
> +                       Decoder(5, "REPLAY_ASYNC_EVENT_NET", decode_unimp),
> +]
> +# See replay_read_events/replay_read_event
> +def decode_async(eid, name, dumpfile):
> +    """Decode an ASYNC event"""
> +
> +    print_event(eid, name)
> +
> +    async_event_kind = read_byte(dumpfile)
> +    async_event_checkpoint = read_byte(dumpfile)
> +
> +    if async_event_checkpoint != replay_state.current_checkpoint:
> +        print "  mismatch between checkpoint %d and async data %d" % (
> +            replay_state.current_checkpoint, async_event_checkpoint)
> +        return True
> +
> +    return call_decode(async_decode_table, async_event_kind, dumpfile)
> +
> +
> +def decode_instruction(eid, name, dumpfile):
> +    ins_diff = read_dword(dumpfile)
> +    print_event(eid, name, "0x%x" % (ins_diff))
> +    return True
> +
> +def decode_audio_out(eid, name, dumpfile):
> +    audio_data = read_dword(dumpfile)
> +    print_event(eid, name, "%d" % (audio_data))
> +    return True
> +
> +def decode_checkpoint(eid, name, dumpfile):
> +    """Decode a checkpoint.
> +
> +    Checkpoints contain a series of async events with their own specific data.
> +    """
> +    replay_state.set_checkpoint()
> +    # save event count as we peek ahead
> +    event_number = replay_state.event_count
> +    next_event = read_event(dumpfile)
> +
> +    # if the next event is EVENT_ASYNC there are a bunch of
> +    # async events to read, otherwise we are done
> +    if next_event != 3:
> +        print_event(eid, name, "no additional data", event_number)
> +    else:
> +        print_event(eid, name, "more data follows", event_number)
> +
> +    replay_state.reuse_event(next_event)
> +    return True
> +
> +def decode_checkpoint_init(eid, name, dumpfile):
> +    print_event(eid, name)
> +    return True
> +
> +def decode_interrupt(eid, name, dumpfile):
> +    print_event(eid, name)
> +    return True
> +
> +def decode_clock(eid, name, dumpfile):
> +    clock_data = read_qword(dumpfile)
> +    print_event(eid, name, "0x%x" % (clock_data))
> +    return True
> +
> +
> +# pre-MTTCG merge
> +v5_event_table = [Decoder(0, "EVENT_INSTRUCTION", decode_instruction),
> +                  Decoder(1, "EVENT_INTERRUPT", decode_interrupt),
> +                  Decoder(2, "EVENT_EXCEPTION", decode_unimp),
> +                  Decoder(3, "EVENT_ASYNC", decode_async),
> +                  Decoder(4, "EVENT_SHUTDOWN", decode_unimp),
> +                  Decoder(5, "EVENT_CHAR_WRITE", decode_unimp),
> +                  Decoder(6, "EVENT_CHAR_READ_ALL", decode_unimp),
> +                  Decoder(7, "EVENT_CHAR_READ_ALL_ERROR", decode_unimp),
> +                  Decoder(8, "EVENT_CLOCK_HOST", decode_clock),
> +                  Decoder(9, "EVENT_CLOCK_VIRTUAL_RT", decode_clock),
> +                  Decoder(10, "EVENT_CP_CLOCK_WARP_START", decode_checkpoint),
> +                  Decoder(11, "EVENT_CP_CLOCK_WARP_ACCOUNT", decode_checkpoint),
> +                  Decoder(12, "EVENT_CP_RESET_REQUESTED", decode_checkpoint),
> +                  Decoder(13, "EVENT_CP_SUSPEND_REQUESTED", decode_checkpoint),
> +                  Decoder(14, "EVENT_CP_CLOCK_VIRTUAL", decode_checkpoint),
> +                  Decoder(15, "EVENT_CP_CLOCK_HOST", decode_checkpoint),
> +                  Decoder(16, "EVENT_CP_CLOCK_VIRTUAL_RT", decode_checkpoint),
> +                  Decoder(17, "EVENT_CP_INIT", decode_checkpoint_init),
> +                  Decoder(18, "EVENT_CP_RESET", decode_checkpoint),
> +]
> +
> +# post-MTTCG merge, AUDIO support added
> +v6_event_table = [Decoder(0, "EVENT_INSTRUCTION", decode_instruction),
> +                  Decoder(1, "EVENT_INTERRUPT", decode_interrupt),
> +                  Decoder(2, "EVENT_EXCEPTION", decode_unimp),
> +                  Decoder(3, "EVENT_ASYNC", decode_async),
> +                  Decoder(4, "EVENT_SHUTDOWN", decode_unimp),
> +                  Decoder(5, "EVENT_CHAR_WRITE", decode_unimp),
> +                  Decoder(6, "EVENT_CHAR_READ_ALL", decode_unimp),
> +                  Decoder(7, "EVENT_CHAR_READ_ALL_ERROR", decode_unimp),
> +                  Decoder(8, "EVENT_AUDIO_OUT", decode_audio_out),
> +                  Decoder(9, "EVENT_AUDIO_IN", decode_unimp),
> +                  Decoder(10, "EVENT_CLOCK_HOST", decode_clock),
> +                  Decoder(11, "EVENT_CLOCK_VIRTUAL_RT", decode_clock),
> +                  Decoder(12, "EVENT_CP_CLOCK_WARP_START", decode_checkpoint),
> +                  Decoder(13, "EVENT_CP_CLOCK_WARP_ACCOUNT", decode_checkpoint),
> +                  Decoder(14, "EVENT_CP_RESET_REQUESTED", decode_checkpoint),
> +                  Decoder(15, "EVENT_CP_SUSPEND_REQUESTED", decode_checkpoint),
> +                  Decoder(16, "EVENT_CP_CLOCK_VIRTUAL", decode_checkpoint),
> +                  Decoder(17, "EVENT_CP_CLOCK_HOST", decode_checkpoint),
> +                  Decoder(18, "EVENT_CP_CLOCK_VIRTUAL_RT", decode_checkpoint),
> +                  Decoder(19, "EVENT_CP_INIT", decode_checkpoint_init),
> +                  Decoder(20, "EVENT_CP_RESET", decode_checkpoint),
> +]
> +
> +def parse_arguments():
> +    "Grab arguments for script"
> +    parser = argparse.ArgumentParser()
> +    parser.add_argument("-f", "--file", help='record/replay dump to read from',
> +                        required=True)
> +    return parser.parse_args()
> +
> +def decode_file(filename):
> +    "Decode a record/replay dump"
> +    dumpfile = open(filename, "rb")
> +
> +    # read and throwaway the header
> +    version = read_dword(dumpfile)
> +    junk = read_qword(dumpfile)
> +
> +    print "HEADER: version 0x%x" % (version)
> +    if version == 0xe02006:
> +        event_decode_table = v6_event_table
> +        replay_state.checkpoint_start = 12
> +    else:
> +        event_decode_table = v5_event_table
> +        replay_state.checkpoint_start = 10
> +
> +    try:
> +        decode_ok = True
> +        while decode_ok:
> +            event = read_event(dumpfile)
> +            decode_ok = call_decode(event_decode_table, event, dumpfile)
> +    finally:
> +        dumpfile.close()
> +
> +if __name__ == "__main__":
> +    args = parse_arguments()
> +    decode_file(args.file)
>

Re: [Qemu-devel] [PATCH v2 5/6] cputlb: add trace events

[Philippe Mathieu-Daudé]

On 05/17/2017 11:52 AM, Alex Bennée wrote:
> Given the range of costs for various SoftMMU TLB operations from
> deferring work for the currently running vCPU to bring the whole
> emulated machine to a stop for synchronised updates simple counters
> are less useful. Instead we log events via the trace infrastructure
> and we can then post-process the data in a range of ways.
>
>   tlb_flush_self - the vCPU flushed its own TLB
>   tlb_flush_async_schedule - work was scheduled and the vCPU kicked
>   tlb_flush_synced_schedule - exclusive work was scheduled on a vCPU
>   tlb_flush_work - scheduled work was done
>
> We can use the difference between the work being scheduled and
> tlb_flush_work to calculate the latency introduced.
>
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  cputlb.c     | 34 +++++++++++++++++++++++++++++++++-
>  trace-events |  7 +++++++
>  2 files changed, 40 insertions(+), 1 deletion(-)
>
> diff --git a/cputlb.c b/cputlb.c
> index d1859c3f37..b2490863e4 100644
> --- a/cputlb.c
> +++ b/cputlb.c
> @@ -127,6 +127,7 @@ static void tlb_flush_nocheck(CPUState *cpu)
>
>  static void tlb_flush_global_async_work(CPUState *cpu, run_on_cpu_data data)
>  {
> +    trace_tlb_flush_work(__func__, cpu->cpu_index);
>      tlb_flush_nocheck(cpu);
>  }
>
> @@ -135,17 +136,22 @@ void tlb_flush(CPUState *cpu)
>      if (cpu->created && !qemu_cpu_is_self(cpu)) {
>          if (atomic_mb_read(&cpu->pending_tlb_flush) != ALL_MMUIDX_BITS) {
>              atomic_mb_set(&cpu->pending_tlb_flush, ALL_MMUIDX_BITS);
> +            trace_tlb_flush_async_schedule(__func__, current_cpu ?
> +                                           current_cpu->cpu_index :
> +                                           cpu->cpu_index, cpu->cpu_index);
>              async_run_on_cpu(cpu, tlb_flush_global_async_work,
>                               RUN_ON_CPU_NULL);
>          }
>      } else {
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
> -        tlb_flush_nocheck(cpu);
> +        tlb_flush_global_async_work(cpu, RUN_ON_CPU_NULL);

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

>      }
>  }
>
>  void tlb_flush_all_cpus(CPUState *src_cpu)
>  {
>      const run_on_cpu_func fn = tlb_flush_global_async_work;
> +    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
>      flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
>      fn(src_cpu, RUN_ON_CPU_NULL);
>  }
> @@ -153,6 +159,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;
> +    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
>      flush_all_helper(src_cpu, fn, RUN_ON_CPU_NULL);
>      async_safe_run_on_cpu(src_cpu, fn, RUN_ON_CPU_NULL);
>  }
> @@ -163,6 +170,8 @@ static void tlb_flush_by_mmuidx_async_work(CPUState *cpu, run_on_cpu_data data)
>      unsigned long mmu_idx_bitmask = data.host_int;
>      int mmu_idx;
>
> +    trace_tlb_flush_work(__func__, cpu->cpu_index);
> +
>      assert_cpu_is_self(cpu);
>
>      tb_lock();
> @@ -196,12 +205,16 @@ void tlb_flush_by_mmuidx(CPUState *cpu, uint16_t idxmap)
>
>          if (pending_flushes) {
>              tlb_debug("reduced mmu_idx: 0x%" PRIx16 "\n", pending_flushes);
> +            trace_tlb_flush_async_schedule(__func__,
> +                                           current_cpu->cpu_index,
> +                                           cpu->cpu_index);
>
>              atomic_or(&cpu->pending_tlb_flush, pending_flushes);
>              async_run_on_cpu(cpu, tlb_flush_by_mmuidx_async_work,
>                               RUN_ON_CPU_HOST_INT(pending_flushes));
>          }
>      } else {
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
>          tlb_flush_by_mmuidx_async_work(cpu,
>                                         RUN_ON_CPU_HOST_INT(idxmap));
>      }
> @@ -212,6 +225,7 @@ void tlb_flush_by_mmuidx_all_cpus(CPUState *src_cpu, uint16_t idxmap)
>      const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
>
>      tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
> +    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
>
>      flush_all_helper(src_cpu, fn, RUN_ON_CPU_HOST_INT(idxmap));
>      fn(src_cpu, RUN_ON_CPU_HOST_INT(idxmap));
> @@ -223,6 +237,7 @@ void tlb_flush_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
>      const run_on_cpu_func fn = tlb_flush_by_mmuidx_async_work;
>
>      tlb_debug("mmu_idx: 0x%"PRIx16"\n", idxmap);
> +    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
>
>      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));
> @@ -252,6 +267,7 @@ static void tlb_flush_page_async_work(CPUState *cpu, run_on_cpu_data data)
>      assert_cpu_is_self(cpu);
>
>      tlb_debug("page :" TARGET_FMT_lx "\n", addr);
> +    trace_tlb_flush_work(__func__, cpu->cpu_index);
>
>      /* Check if we need to flush due to large pages.  */
>      if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
> @@ -285,9 +301,12 @@ void tlb_flush_page(CPUState *cpu, target_ulong addr)
>      tlb_debug("page :" TARGET_FMT_lx "\n", addr);
>
>      if (!qemu_cpu_is_self(cpu)) {
> +        trace_tlb_flush_async_schedule(__func__, current_cpu->cpu_index,
> +                                       cpu->cpu_index);
>          async_run_on_cpu(cpu, tlb_flush_page_async_work,
>                           RUN_ON_CPU_TARGET_PTR(addr));
>      } else {
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
>          tlb_flush_page_async_work(cpu, RUN_ON_CPU_TARGET_PTR(addr));
>      }
>  }
> @@ -312,6 +331,7 @@ static void tlb_flush_page_by_mmuidx_async_work(CPUState *cpu,
>
>      tlb_debug("page:%d addr:"TARGET_FMT_lx" mmu_idx:0x%lx\n",
>                page, addr, mmu_idx_bitmap);
> +    trace_tlb_flush_work(__func__, cpu->cpu_index);
>
>      for (mmu_idx = 0; mmu_idx < NB_MMU_MODES; mmu_idx++) {
>          if (test_bit(mmu_idx, &mmu_idx_bitmap)) {
> @@ -336,6 +356,7 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
>      unsigned long mmu_idx_bitmap = addr_and_mmuidx & ALL_MMUIDX_BITS;
>
>      tlb_debug("addr:"TARGET_FMT_lx" mmu_idx: %04lx\n", addr, mmu_idx_bitmap);
> +    trace_tlb_flush_work(__func__, cpu->cpu_index);
>
>      /* Check if we need to flush due to large pages.  */
>      if ((addr & env->tlb_flush_mask) == env->tlb_flush_addr) {
> @@ -343,9 +364,11 @@ static void tlb_check_page_and_flush_by_mmuidx_async_work(CPUState *cpu,
>                    TARGET_FMT_lx "/" TARGET_FMT_lx ")\n",
>                    env->tlb_flush_addr, env->tlb_flush_mask);
>
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
>          tlb_flush_by_mmuidx_async_work(cpu,
>                                         RUN_ON_CPU_HOST_INT(mmu_idx_bitmap));
>      } else {
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
>          tlb_flush_page_by_mmuidx_async_work(cpu, data);
>      }
>  }
> @@ -361,9 +384,12 @@ void tlb_flush_page_by_mmuidx(CPUState *cpu, target_ulong addr, uint16_t idxmap)
>      addr_and_mmu_idx |= idxmap;
>
>      if (!qemu_cpu_is_self(cpu)) {
> +        trace_tlb_flush_async_schedule(__func__, current_cpu->cpu_index,
> +                                       cpu->cpu_index);
>          async_run_on_cpu(cpu, tlb_check_page_and_flush_by_mmuidx_async_work,
>                           RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
>      } else {
> +        trace_tlb_flush_self(__func__, cpu->cpu_index);
>          tlb_check_page_and_flush_by_mmuidx_async_work(
>              cpu, RUN_ON_CPU_TARGET_PTR(addr_and_mmu_idx));
>      }
> @@ -376,6 +402,7 @@ void tlb_flush_page_by_mmuidx_all_cpus(CPUState *src_cpu, target_ulong addr,
>      target_ulong addr_and_mmu_idx;
>
>      tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
> +    trace_tlb_flush_async_schedule(__func__, src_cpu->cpu_index, -1);
>
>      /* This should already be page aligned */
>      addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
> @@ -393,6 +420,7 @@ void tlb_flush_page_by_mmuidx_all_cpus_synced(CPUState *src_cpu,
>      target_ulong addr_and_mmu_idx;
>
>      tlb_debug("addr: "TARGET_FMT_lx" mmu_idx:%"PRIx16"\n", addr, idxmap);
> +    trace_tlb_flush_synced_schedule(__func__, src_cpu->cpu_index, -1);
>
>      /* This should already be page aligned */
>      addr_and_mmu_idx = addr & TARGET_PAGE_MASK;
> @@ -406,6 +434,8 @@ void tlb_flush_page_all_cpus(CPUState *src, target_ulong addr)
>  {
>      const run_on_cpu_func fn = tlb_flush_page_async_work;
>
> +    trace_tlb_flush_async_schedule(__func__, src->cpu_index, -1);
> +
>      flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
>      fn(src, RUN_ON_CPU_TARGET_PTR(addr));
>  }
> @@ -415,6 +445,8 @@ void tlb_flush_page_all_cpus_synced(CPUState *src,
>  {
>      const run_on_cpu_func fn = tlb_flush_page_async_work;
>
> +    trace_tlb_flush_synced_schedule(__func__, src->cpu_index, -1);
> +
>      flush_all_helper(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
>      async_safe_run_on_cpu(src, fn, RUN_ON_CPU_TARGET_PTR(addr));
>  }
> diff --git a/trace-events b/trace-events
> index e582d6315d..500f84b8c4 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -78,6 +78,13 @@ 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"
>
> +# SoftMMU TLB flushes
> +#   - setting to=-1 indicates work scheduled on all vCPUs
> +tlb_flush_self(const char *fn, int vcpu) "%s: cpu %d"
> +tlb_flush_async_schedule(const char *fn, int from, int to) "%s: from_cpu=%d to_cpu=%d"
> +tlb_flush_synced_schedule(const char *fn, int from, int to) "%s: from_cpu=%d to_cpu=%d"
> +tlb_flush_work(const char *fn, int vcpu) "%s: cpu %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 v2 6/6] new script/analyse-tlb-flushes-simpletrace.py

[Alex Bennée]

Pranith Kumar <bobby.prani+qemu@gmail.com> writes:

> Hi Alex,
>
> Please find some comments and questions below:
>
> On Wed, May 17, 2017 at 10:52 AM, Alex Bennée <alex.bennee@linaro.org> wrote:
>> 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>
>>
>> ---
>> v2
>>   - re-factored for new trace events
>>   - added time and latency graphs
>> ---
>>  scripts/analyse-tlb-flushes-simpletrace.py | 144 +++++++++++++++++++++++++++++
>>  1 file changed, 144 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..03fab8c86b
>> --- /dev/null
>> +++ b/scripts/analyse-tlb-flushes-simpletrace.py
>
> <snip>
>
>> +
>> +def get_args():
>> +    "Grab options"
>> +    parser = argparse.ArgumentParser()
>> +    parser.add_argument("--output", "-o", type=str, help="Render plot to file")
>> +    parser.add_argument("--vcpus", type=int, help="Number of vCPUS")
>
> It is not really clear what this argument is for. I guess you are
> saying how many cpus the guest from which trace file was generated
> had? What happens if we pass in less number of vcpus than used for
> generation?

Yeah it's a bit of a hack. I need to know how many vcpus there are so
when we save an "all vcpu" event we can set the event in:

    def __save_queue(self, vcpu, record):
        self.flush_total += 1
        # FIXME: don't seem to see -1
        if vcpu > 0x7fffffff:
            self.flush_all += 1
            for i in range(0, self.nvcpus):
                self.vcpu_last[i].append(record)
        else:
            self.vcpu_last[vcpu].append(record)


>
>> +    parser.add_argument("--graph", choices=['time', 'latency'], default='time')
>
> What does latency here indicate? I tried this argument on a sample
> trace file I generated, and it had three empty boxes.

Time just tracks the culmlative total of flush events over time where as
latency gives a distribution of time from queuing the flush event to it
being processed.

>
>> +    parser.add_argument("events", type=str, help='trace file read from')
>> +    parser.add_argument("tracefile", type=str, help='trace file read from')
>
> The help text for 'events' file here should be something like 'the
> trace events file'.

Good catch, will fix.

>
> Thanks,


--
Alex Bennée