[PATCH v2 00/12] simpletrace: refactor and general improvements

[PATCH v2 00/12] simpletrace: refactor and general improvements

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

I wanted to use simpletrace.py for an internal project, so I tried to update
and polish the code. Some of the commits resolve specific issues, while some
are more subjective.

I've tried to divide it into commits so we can discuss the
individual changes, and I'm ready to pull things out, if it isn't needed.

v2:
 * Added myself as maintainer of simpletrace.py
 * Improve docstring on `process`
 * Changed call to `process` in scripts/analyse-locks-simpletrace.py to reflect new argument types
 * Replaced `iteritems()` with `items()` in scripts/analyse-locks-simpletrace.py to support Python 3

Mads Ynddal (12):
  simpletrace: Improve parsing of sys.argv; fix files never closed.
  simpletrace: Annotate magic constants from QEMU code
  simpletrace: changed naming of edict and idtoname to improve
    readability
  simpletrace: update code for Python 3.11
  simpletrace: Changed Analyzer class to become context-manager
  simpletrace: Simplify construction of tracing methods
  simpletrace: Improved error handling on struct unpack
  simpletrace: define exception and add handling
  simpletrace: Refactor to separate responsibilities
  MAINTAINERS: add maintainer of simpletrace.py
  scripts/analyse-locks-simpletrace.py: changed iteritems() to items()
  scripts/analyse-locks-simpletrace.py: reflect changes to process in
    simpletrace.py

 MAINTAINERS                          |   8 +-
 scripts/analyse-locks-simpletrace.py |   5 +-
 scripts/simpletrace.py               | 307 ++++++++++++---------------
 3 files changed, 150 insertions(+), 170 deletions(-)

-- 
2.38.1

[PATCH v2 01/12] simpletrace: Improve parsing of sys.argv; fix files never closed.

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

The arguments extracted from `sys.argv` named and unpacked to make it
clear what the arguments are and what they're used for.

The two input files were opened, but never explicitly closed. File usage
changed to use `with` statement to take care of this. At the same time,
ownership of the file-object is moved up to `run` function. Secondary `open`
inside `process` removed so there's only one place to handle `open`.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 28 +++++++++++-----------------
 1 file changed, 11 insertions(+), 17 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 1f6d1ae1f3..9211caaec1 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -9,6 +9,7 @@
 #
 # For help see docs/devel/tracing.rst
 
+import sys
 import struct
 import inspect
 from tracetool import read_events, Event
@@ -44,7 +45,6 @@ def get_record(edict, idtoname, rechdr, fobj):
         try:
             event = edict[name]
         except KeyError as e:
-            import sys
             sys.stderr.write('%s event is logged but is not declared ' \
                              'in the trace events file, try using ' \
                              'trace-events-all instead.\n' % str(e))
@@ -166,11 +166,6 @@ def end(self):
 
 def process(events, log, analyzer, read_header=True):
     """Invoke an analyzer on each event in a log."""
-    if isinstance(events, str):
-        events = read_events(open(events, 'r'), events)
-    if isinstance(log, str):
-        log = open(log, 'rb')
-
     if read_header:
         read_trace_header(log)
 
@@ -223,19 +218,18 @@ def run(analyzer):
 
     This function is useful as a driver for simple analysis scripts.  More
     advanced scripts will want to call process() instead."""
-    import sys
-
-    read_header = True
-    if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
-        read_header = False
-        del sys.argv[1]
-    elif len(sys.argv) != 3:
-        sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
-                         '<trace-file>\n' % sys.argv[0])
+
+    try:
+        # NOTE: See built-in `argparse` module for a more robust cli interface
+        *no_header, trace_event_path, trace_file_path = sys.argv[1:]
+        assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument'
+    except (AssertionError, ValueError):
+        sys.stderr.write(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
         sys.exit(1)
 
-    events = read_events(open(sys.argv[1], 'r'), sys.argv[1])
-    process(events, sys.argv[2], analyzer, read_header=read_header)
+    with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj:
+        events = read_events(events_fobj, trace_event_path)
+        process(events, log_fobj, analyzer, read_header=not no_header)
 
 if __name__ == '__main__':
     class Formatter(Analyzer):
-- 
2.38.1

[PATCH v2 02/12] simpletrace: Annotate magic constants from QEMU code

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

It wasn't clear where the constants and structs came from, so I added
comments to help.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 9211caaec1..7ba805443d 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -15,15 +15,15 @@
 from tracetool import read_events, Event
 from tracetool.backend.simple import is_string
 
-header_event_id = 0xffffffffffffffff
-header_magic    = 0xf2b177cb0aa429b4
-dropped_event_id = 0xfffffffffffffffe
+header_event_id = 0xffffffffffffffff # trace/simple.c::HEADER_EVENT_ID
+header_magic    = 0xf2b177cb0aa429b4 # trace/simple.c::HEADER_MAGIC
+dropped_event_id = 0xfffffffffffffffe # trace/simple.c::DROPPED_EVENT_ID
 
-record_type_mapping = 0
-record_type_event = 1
+record_type_mapping = 0 # trace/simple.c::TRACE_RECORD_TYPE_MAPPING
+record_type_event = 1 # trace/simple.c::TRACE_RECORD_TYPE_EVENT
 
-log_header_fmt = '=QQQ'
-rec_header_fmt = '=QQII'
+log_header_fmt = '=QQQ' # trace/simple.c::TraceLogHeader
+rec_header_fmt = '=QQII' # trace/simple.c::TraceRecord
 
 def read_header(fobj, hfmt):
     '''Read a trace record header'''
-- 
2.38.1

[PATCH v2 03/12] simpletrace: changed naming of edict and idtoname to improve readability

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

Readability is subjective, but I've expanded the naming of the variables
and arguments, to help with understanding for new eyes on the code.

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 34 +++++++++++++++++-----------------
 1 file changed, 17 insertions(+), 17 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 7ba805443d..9981699630 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -33,17 +33,17 @@ def read_header(fobj, hfmt):
         return None
     return struct.unpack(hfmt, hdr)
 
-def get_record(edict, idtoname, rechdr, fobj):
+def get_record(event_mapping, event_id_to_name, rechdr, fobj):
     """Deserialize a trace record from a file into a tuple
        (name, timestamp, pid, arg1, ..., arg6)."""
     if rechdr is None:
         return None
     if rechdr[0] != dropped_event_id:
         event_id = rechdr[0]
-        name = idtoname[event_id]
+        name = event_id_to_name[event_id]
         rec = (name, rechdr[1], rechdr[3])
         try:
-            event = edict[name]
+            event = event_mapping[name]
         except KeyError as e:
             sys.stderr.write('%s event is logged but is not declared ' \
                              'in the trace events file, try using ' \
@@ -72,10 +72,10 @@ def get_mapping(fobj):
 
     return (event_id, name)
 
-def read_record(edict, idtoname, fobj):
+def read_record(event_mapping, event_id_to_name, fobj):
     """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
     rechdr = read_header(fobj, rec_header_fmt)
-    return get_record(edict, idtoname, rechdr, fobj)
+    return get_record(event_mapping, event_id_to_name, rechdr, fobj)
 
 def read_trace_header(fobj):
     """Read and verify trace file header"""
@@ -96,14 +96,14 @@ def read_trace_header(fobj):
         raise ValueError('Log format %d not supported with this QEMU release!'
                          % log_version)
 
-def read_trace_records(edict, idtoname, fobj):
+def read_trace_records(event_mapping, event_id_to_name, fobj):
     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).
 
-    Note that `idtoname` is modified if the file contains mapping records.
+    Note that `event_id_to_name` is modified if the file contains mapping records.
 
     Args:
-        edict (str -> Event): events dict, indexed by name
-        idtoname (int -> str): event names dict, indexed by event ID
+        event_mapping (str -> Event): events dict, indexed by name
+        event_id_to_name (int -> str): event names dict, indexed by event ID
         fobj (file): input file
 
     """
@@ -115,9 +115,9 @@ def read_trace_records(edict, idtoname, fobj):
         (rectype, ) = struct.unpack('=Q', t)
         if rectype == record_type_mapping:
             event_id, name = get_mapping(fobj)
-            idtoname[event_id] = name
+            event_id_to_name[event_id] = name
         else:
-            rec = read_record(edict, idtoname, fobj)
+            rec = read_record(event_mapping, event_id_to_name, fobj)
 
             yield rec
 
@@ -172,16 +172,16 @@ def process(events, log, analyzer, read_header=True):
     frameinfo = inspect.getframeinfo(inspect.currentframe())
     dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)",
                                 frameinfo.lineno + 1, frameinfo.filename)
-    edict = {"dropped": dropped_event}
-    idtoname = {dropped_event_id: "dropped"}
+    event_mapping = {"dropped": dropped_event}
+    event_id_to_name = {dropped_event_id: "dropped"}
 
     for event in events:
-        edict[event.name] = event
+        event_mapping[event.name] = event
 
     # If there is no header assume event ID mapping matches events list
     if not read_header:
         for event_id, event in enumerate(events):
-            idtoname[event_id] = event.name
+            event_id_to_name[event_id] = event.name
 
     def build_fn(analyzer, event):
         if isinstance(event, str):
@@ -205,9 +205,9 @@ def build_fn(analyzer, event):
 
     analyzer.begin()
     fn_cache = {}
-    for rec in read_trace_records(edict, idtoname, log):
+    for rec in read_trace_records(event_mapping, event_id_to_name, log):
         event_num = rec[0]
-        event = edict[event_num]
+        event = event_mapping[event_num]
         if event_num not in fn_cache:
             fn_cache[event_num] = build_fn(analyzer, event)
         fn_cache[event_num](event, rec)
-- 
2.38.1

[PATCH v2 04/12] simpletrace: update code for Python 3.11

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

The call to `getargspec` was deprecated and in Python 3.11 it has been
removed in favor of `getfullargspec`.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 9981699630..7444a6e090 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -192,7 +192,7 @@ def build_fn(analyzer, event):
             return analyzer.catchall
 
         event_argcount = len(event.args)
-        fn_argcount = len(inspect.getargspec(fn)[0]) - 1
+        fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1
         if fn_argcount == event_argcount + 1:
             # Include timestamp as first argument
             return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount]))
-- 
2.38.1

[PATCH v2 05/12] simpletrace: Changed Analyzer class to become context-manager

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

Instead of explicitly calling `begin` and `end`, we can change the class
to use the context-manager paradigm. This is mostly a styling choice,
used in modern Python code. But it also allows for more advanced analyzers
to handle exceptions gracefully in the `__exit__` method (not
demonstrated here).

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 40 +++++++++++++++++++++++-----------------
 1 file changed, 23 insertions(+), 17 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 7444a6e090..10ca093046 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -121,12 +121,12 @@ def read_trace_records(event_mapping, event_id_to_name, fobj):
 
             yield rec
 
-class Analyzer(object):
+class Analyzer:
     """A trace file analyzer which processes trace records.
 
-    An analyzer can be passed to run() or process().  The begin() method is
-    invoked, then each trace record is processed, and finally the end() method
-    is invoked.
+    An analyzer can be passed to run() or process().  The __enter__() method is
+    invoked when opening the analyzer using the `with` statement, then each trace
+    record is processed, and finally the __exit__() method is invoked.
 
     If a method matching a trace event name exists, it is invoked to process
     that trace record.  Otherwise the catchall() method is invoked.
@@ -152,19 +152,25 @@ def runstate_set(self, timestamp, pid, new_state):
           ...
     """
 
-    def begin(self):
+    def __enter__(self):
         """Called at the start of the trace."""
-        pass
+        return self
 
     def catchall(self, event, rec):
         """Called if no specific method for processing a trace event has been found."""
         pass
 
-    def end(self):
+    def __exit__(self, _type, value, traceback):
         """Called at the end of the trace."""
         pass
 
-def process(events, log, analyzer, read_header=True):
+    def __call__(self):
+        """Fix for legacy use without context manager.
+        We call the provided object in `process` regardless of it being the object-type or instance.
+        With this function, it will work in both cases."""
+        return self
+
+def process(events, log, analyzer_class, read_header=True):
     """Invoke an analyzer on each event in a log."""
     if read_header:
         read_trace_header(log)
@@ -203,15 +209,15 @@ def build_fn(analyzer, event):
             # Just arguments, no timestamp or pid
             return lambda _, rec: fn(*rec[3:3 + event_argcount])
 
-    analyzer.begin()
-    fn_cache = {}
-    for rec in read_trace_records(event_mapping, event_id_to_name, log):
-        event_num = rec[0]
-        event = event_mapping[event_num]
-        if event_num not in fn_cache:
-            fn_cache[event_num] = build_fn(analyzer, event)
-        fn_cache[event_num](event, rec)
-    analyzer.end()
+    with analyzer_class() as analyzer:
+        fn_cache = {}
+        for rec in read_trace_records(event_mapping, event_id_to_name, log):
+            event_num = rec[0]
+            event = event_mapping[event_num]
+            if event_num not in fn_cache:
+                fn_cache[event_num] = build_fn(analyzer, event)
+            fn_cache[event_num](event, rec)
+
 
 def run(analyzer):
     """Execute an analyzer on a trace file given on the command-line.
-- 
2.38.1

[PATCH v2 06/12] simpletrace: Simplify construction of tracing methods

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

By moving the dynamic argument construction to keyword-arguments,
we can remove all of the specialized handling, and streamline it.
If a tracing method wants to access these, they can define the
kwargs, or ignore it be placing `**kwargs` at the end of the
function's arguments list.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 84 ++++++++++++++++--------------------------
 1 file changed, 32 insertions(+), 52 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 10ca093046..f6b40d56f6 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -131,16 +131,25 @@ class Analyzer:
     If a method matching a trace event name exists, it is invoked to process
     that trace record.  Otherwise the catchall() method is invoked.
 
+    The methods are called with a set of keyword-arguments. These can be ignored
+    using `**kwargs` or defined like any keyword-argument.
+
+    The following keyword-arguments are available:
+        event: Event object of current trace
+        event_id: The id of the event in the current trace file
+        timestamp_ns: The timestamp in nanoseconds of the trace
+        pid: The process id recorded for the given trace
+
     Example:
     The following method handles the runstate_set(int new_state) trace event::
 
-      def runstate_set(self, new_state):
+      def runstate_set(self, new_state, **kwargs):
           ...
 
-    The method can also take a timestamp argument before the trace event
-    arguments::
+    The method can also explicitly take a timestamp keyword-argument with the
+    trace event arguments::
 
-      def runstate_set(self, timestamp, new_state):
+      def runstate_set(self, new_state, *, timestamp, **kwargs):
           ...
 
     Timestamps have the uint64_t type and are in nanoseconds.
@@ -148,7 +157,7 @@ def runstate_set(self, timestamp, new_state):
     The pid can be included in addition to the timestamp and is useful when
     dealing with traces from multiple processes::
 
-      def runstate_set(self, timestamp, pid, new_state):
+      def runstate_set(self, new_state, *, timestamp, pid, **kwargs):
           ...
     """
 
@@ -156,7 +165,7 @@ def __enter__(self):
         """Called at the start of the trace."""
         return self
 
-    def catchall(self, event, rec):
+    def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
         """Called if no specific method for processing a trace event has been found."""
         pass
 
@@ -189,34 +198,11 @@ def process(events, log, analyzer_class, read_header=True):
         for event_id, event in enumerate(events):
             event_id_to_name[event_id] = event.name
 
-    def build_fn(analyzer, event):
-        if isinstance(event, str):
-            return analyzer.catchall
-
-        fn = getattr(analyzer, event.name, None)
-        if fn is None:
-            return analyzer.catchall
-
-        event_argcount = len(event.args)
-        fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1
-        if fn_argcount == event_argcount + 1:
-            # Include timestamp as first argument
-            return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount]))
-        elif fn_argcount == event_argcount + 2:
-            # Include timestamp and pid
-            return lambda _, rec: fn(*rec[1:3 + event_argcount])
-        else:
-            # Just arguments, no timestamp or pid
-            return lambda _, rec: fn(*rec[3:3 + event_argcount])
-
     with analyzer_class() as analyzer:
-        fn_cache = {}
-        for rec in read_trace_records(event_mapping, event_id_to_name, log):
-            event_num = rec[0]
-            event = event_mapping[event_num]
-            if event_num not in fn_cache:
-                fn_cache[event_num] = build_fn(analyzer, event)
-            fn_cache[event_num](event, rec)
+        for event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(event_mapping, event_id_to_name, log):
+            event = event_mapping[event_id]
+            fn = getattr(analyzer, event.name, analyzer.catchall)
+            fn(*rec_args, event=event, event_id=event_id, timestamp_ns=timestamp_ns, pid=record_pid)
 
 
 def run(analyzer):
@@ -240,24 +226,18 @@ def run(analyzer):
 if __name__ == '__main__':
     class Formatter(Analyzer):
         def __init__(self):
-            self.last_timestamp = None
-
-        def catchall(self, event, rec):
-            timestamp = rec[1]
-            if self.last_timestamp is None:
-                self.last_timestamp = timestamp
-            delta_ns = timestamp - self.last_timestamp
-            self.last_timestamp = timestamp
-
-            fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
-                      'pid=%d' % rec[2]]
-            i = 3
-            for type, name in event.args:
-                if is_string(type):
-                    fields.append('%s=%s' % (name, rec[i]))
-                else:
-                    fields.append('%s=0x%x' % (name, rec[i]))
-                i += 1
-            print(' '.join(fields))
+            self.last_timestamp_ns = None
+
+        def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
+            if self.last_timestamp_ns is None:
+                self.last_timestamp_ns = timestamp_ns
+            delta_ns = timestamp_ns - self.last_timestamp_ns
+            self.last_timestamp_ns = timestamp_ns
+
+            fields = [
+                f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}'
+                for r, (type, name) in zip(rec_args, event.args)
+            ]
+            print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields))
 
     run(Formatter())
-- 
2.38.1

[PATCH v2 07/12] simpletrace: Improved error handling on struct unpack

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

A failed call to `read_header` wouldn't be handled the same for the two
different code paths (one path would try to use `None` as a list).
Changed to raise exception to be handled centrally. This also allows for
easier unpacking, as errors has been filtered out.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 41 ++++++++++++++++-------------------------
 1 file changed, 16 insertions(+), 25 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index f6b40d56f6..e77cb2469c 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -30,26 +30,24 @@ def read_header(fobj, hfmt):
     hlen = struct.calcsize(hfmt)
     hdr = fobj.read(hlen)
     if len(hdr) != hlen:
-        return None
+        raise ValueError('Error reading header. Wrong filetype provided?')
     return struct.unpack(hfmt, hdr)
 
 def get_record(event_mapping, event_id_to_name, rechdr, fobj):
     """Deserialize a trace record from a file into a tuple
        (name, timestamp, pid, arg1, ..., arg6)."""
-    if rechdr is None:
-        return None
-    if rechdr[0] != dropped_event_id:
-        event_id = rechdr[0]
+    event_id, timestamp_ns, length, pid = rechdr
+    if event_id != dropped_event_id:
         name = event_id_to_name[event_id]
-        rec = (name, rechdr[1], rechdr[3])
         try:
             event = event_mapping[name]
         except KeyError as e:
-            sys.stderr.write('%s event is logged but is not declared ' \
+            sys.stderr.write(f'{e} event is logged but is not declared ' \
                              'in the trace events file, try using ' \
-                             'trace-events-all instead.\n' % str(e))
+                             'trace-events-all instead.\n')
             sys.exit(1)
 
+        rec = (name, timestamp_ns, pid)
         for type, name in event.args:
             if is_string(type):
                 l = fobj.read(4)
@@ -60,9 +58,8 @@ def get_record(event_mapping, event_id_to_name, rechdr, fobj):
                 (value,) = struct.unpack('=Q', fobj.read(8))
                 rec = rec + (value,)
     else:
-        rec = ("dropped", rechdr[1], rechdr[3])
-        (value,) = struct.unpack('=Q', fobj.read(8))
-        rec = rec + (value,)
+        (dropped_count,) = struct.unpack('=Q', fobj.read(8))
+        rec = ("dropped", timestamp_ns, pid, dropped_count)
     return rec
 
 def get_mapping(fobj):
@@ -79,22 +76,16 @@ def read_record(event_mapping, event_id_to_name, fobj):
 
 def read_trace_header(fobj):
     """Read and verify trace file header"""
-    header = read_header(fobj, log_header_fmt)
-    if header is None:
-        raise ValueError('Not a valid trace file!')
-    if header[0] != header_event_id:
-        raise ValueError('Not a valid trace file, header id %d != %d' %
-                         (header[0], header_event_id))
-    if header[1] != header_magic:
-        raise ValueError('Not a valid trace file, header magic %d != %d' %
-                         (header[1], header_magic))
-
-    log_version = header[2]
+    _header_event_id, _header_magic, log_version = read_header(fobj, log_header_fmt)
+    if _header_event_id != header_event_id:
+        raise ValueError(f'Not a valid trace file, header id {_header_event_id} != {header_event_id}')
+    if _header_magic != header_magic:
+        raise ValueError(f'Not a valid trace file, header magic {_header_magic} != {header_magic}')
+
     if log_version not in [0, 2, 3, 4]:
-        raise ValueError('Unknown version of tracelog format!')
+        raise ValueError(f'Unknown version {log_version} of tracelog format!')
     if log_version != 4:
-        raise ValueError('Log format %d not supported with this QEMU release!'
-                         % log_version)
+        raise ValueError(f'Log format {log_version} not supported with this QEMU release!')
 
 def read_trace_records(event_mapping, event_id_to_name, fobj):
     """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).
-- 
2.38.1

[PATCH v2 08/12] simpletrace: define exception and add handling

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

Define `SimpleException` to differentiate our exceptions from generic
exceptions (IOError, etc.). Adapted simpletrace to support this and
output to stderr.

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 22 ++++++++++++++--------
 1 file changed, 14 insertions(+), 8 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index e77cb2469c..3cf34103e4 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -25,12 +25,15 @@
 log_header_fmt = '=QQQ' # trace/simple.c::TraceLogHeader
 rec_header_fmt = '=QQII' # trace/simple.c::TraceRecord
 
+class SimpleException(Exception):
+    pass
+
 def read_header(fobj, hfmt):
     '''Read a trace record header'''
     hlen = struct.calcsize(hfmt)
     hdr = fobj.read(hlen)
     if len(hdr) != hlen:
-        raise ValueError('Error reading header. Wrong filetype provided?')
+        raise SimpleException('Error reading header. Wrong filetype provided?')
     return struct.unpack(hfmt, hdr)
 
 def get_record(event_mapping, event_id_to_name, rechdr, fobj):
@@ -42,10 +45,10 @@ def get_record(event_mapping, event_id_to_name, rechdr, fobj):
         try:
             event = event_mapping[name]
         except KeyError as e:
-            sys.stderr.write(f'{e} event is logged but is not declared ' \
-                             'in the trace events file, try using ' \
-                             'trace-events-all instead.\n')
-            sys.exit(1)
+            raise SimpleException(
+                f'{e} event is logged but is not declared in the trace events'
+                'file, try using trace-events-all instead.'
+            )
 
         rec = (name, timestamp_ns, pid)
         for type, name in event.args:
@@ -207,8 +210,7 @@ def run(analyzer):
         *no_header, trace_event_path, trace_file_path = sys.argv[1:]
         assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument'
     except (AssertionError, ValueError):
-        sys.stderr.write(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
-        sys.exit(1)
+        raise SimpleException(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
 
     with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj:
         events = read_events(events_fobj, trace_event_path)
@@ -231,4 +233,8 @@ def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
             ]
             print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields))
 
-    run(Formatter())
+    try:
+        run(Formatter())
+    except SimpleException as e:
+        sys.stderr.write(e + "\n")
+        sys.exit(1)
-- 
2.38.1

[PATCH v2 09/12] simpletrace: Refactor to separate responsibilities

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

NOTE: `process` changes function signature

Moved event_mapping and event_id_to_name down one level in the function
call-stack to keep variable instantiation and usage closer (`process`
and `run` has no use of the variables; `read_trace_records` does).

Instead of passing event_mapping and event_id_to_name to the bottom of
the call-stack, we move their use to `read_trace_records`. This
separates responsibility and ownership of the information.

`read_record` now just reads the arguments from the file-object by
knowning the total number of bytes. Parsing it to specific arguments is
moved up to `read_trace_records`.

Special handling of dropped events removed, as they can be handled
by the general code.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/simpletrace.py | 130 ++++++++++++++++++++---------------------
 1 file changed, 63 insertions(+), 67 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 3cf34103e4..2fcbcb77d0 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -24,6 +24,7 @@
 
 log_header_fmt = '=QQQ' # trace/simple.c::TraceLogHeader
 rec_header_fmt = '=QQII' # trace/simple.c::TraceRecord
+rec_header_fmt_len = struct.calcsize(rec_header_fmt)
 
 class SimpleException(Exception):
     pass
@@ -36,35 +37,6 @@ def read_header(fobj, hfmt):
         raise SimpleException('Error reading header. Wrong filetype provided?')
     return struct.unpack(hfmt, hdr)
 
-def get_record(event_mapping, event_id_to_name, rechdr, fobj):
-    """Deserialize a trace record from a file into a tuple
-       (name, timestamp, pid, arg1, ..., arg6)."""
-    event_id, timestamp_ns, length, pid = rechdr
-    if event_id != dropped_event_id:
-        name = event_id_to_name[event_id]
-        try:
-            event = event_mapping[name]
-        except KeyError as e:
-            raise SimpleException(
-                f'{e} event is logged but is not declared in the trace events'
-                'file, try using trace-events-all instead.'
-            )
-
-        rec = (name, timestamp_ns, pid)
-        for type, name in event.args:
-            if is_string(type):
-                l = fobj.read(4)
-                (len,) = struct.unpack('=L', l)
-                s = fobj.read(len)
-                rec = rec + (s,)
-            else:
-                (value,) = struct.unpack('=Q', fobj.read(8))
-                rec = rec + (value,)
-    else:
-        (dropped_count,) = struct.unpack('=Q', fobj.read(8))
-        rec = ("dropped", timestamp_ns, pid, dropped_count)
-    return rec
-
 def get_mapping(fobj):
     (event_id, ) = struct.unpack('=Q', fobj.read(8))
     (len, ) = struct.unpack('=L', fobj.read(4))
@@ -72,10 +44,11 @@ def get_mapping(fobj):
 
     return (event_id, name)
 
-def read_record(event_mapping, event_id_to_name, fobj):
-    """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, arg1, ..., arg6)."""
-    rechdr = read_header(fobj, rec_header_fmt)
-    return get_record(event_mapping, event_id_to_name, rechdr, fobj)
+def read_record(fobj):
+    """Deserialize a trace record from a file into a tuple (event_num, timestamp, pid, args)."""
+    event_id, timestamp_ns, record_length, record_pid = read_header(fobj, rec_header_fmt)
+    args_payload = fobj.read(record_length - rec_header_fmt_len)
+    return (event_id, timestamp_ns, record_pid, args_payload)
 
 def read_trace_header(fobj):
     """Read and verify trace file header"""
@@ -90,30 +63,60 @@ def read_trace_header(fobj):
     if log_version != 4:
         raise ValueError(f'Log format {log_version} not supported with this QEMU release!')
 
-def read_trace_records(event_mapping, event_id_to_name, fobj):
-    """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).
-
-    Note that `event_id_to_name` is modified if the file contains mapping records.
+def read_trace_records(events, fobj, read_header):
+    """Deserialize trace records from a file, yielding record tuples (event, event_num, timestamp, pid, arg1, ..., arg6).
 
     Args:
         event_mapping (str -> Event): events dict, indexed by name
-        event_id_to_name (int -> str): event names dict, indexed by event ID
         fobj (file): input file
+        read_header (bool): whether headers were read from fobj
 
     """
-    while True:
-        t = fobj.read(8)
-        if len(t) == 0:
-            break
+    frameinfo = inspect.getframeinfo(inspect.currentframe())
+    dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)",
+                                frameinfo.lineno + 1, frameinfo.filename)
+
+    event_mapping = {e.name: e for e in events}
+    event_mapping["dropped"] = dropped_event
+    event_id_to_name = {dropped_event_id: "dropped"}
 
+    # If there is no header assume event ID mapping matches events list
+    if not read_header:
+        for event_id, event in enumerate(events):
+            event_id_to_name[event_id] = event.name
+
+    while t := fobj.read(8):
         (rectype, ) = struct.unpack('=Q', t)
         if rectype == record_type_mapping:
-            event_id, name = get_mapping(fobj)
-            event_id_to_name[event_id] = name
+            event_id, event_name = get_mapping(fobj)
+            event_id_to_name[event_id] = event_name
         else:
-            rec = read_record(event_mapping, event_id_to_name, fobj)
-
-            yield rec
+            event_id, timestamp_ns, pid, args_payload = read_record(fobj)
+            event_name = event_id_to_name[event_id]
+
+            try:
+                event = event_mapping[event_name]
+            except KeyError as e:
+                raise SimpleException(
+                    f'{e} event is logged but is not declared in the trace events'
+                    'file, try using trace-events-all instead.'
+                )
+
+            offset = 0
+            args = []
+            for type, _ in event.args:
+                if is_string(type):
+                    (len,) = struct.unpack_from('=L', args_payload, offset=offset)
+                    offset += 4
+                    s = args_payload[offset:offset+len]
+                    offset += len
+                    args.append(s)
+                else:
+                    (value,) = struct.unpack_from('=Q', args_payload, offset=offset)
+                    offset += 8
+                    args.append(value)
+
+            yield (event_mapping[event_name], event_name, timestamp_ns, pid) + tuple(args)
 
 class Analyzer:
     """A trace file analyzer which processes trace records.
@@ -173,28 +176,22 @@ def __call__(self):
         With this function, it will work in both cases."""
         return self
 
-def process(events, log, analyzer_class, read_header=True):
-    """Invoke an analyzer on each event in a log."""
-    if read_header:
-        read_trace_header(log)
+def process(events_fobj, log_fobj, analyzer_class, read_header=True):
+    """Invoke an analyzer on each event in a log.
 
-    frameinfo = inspect.getframeinfo(inspect.currentframe())
-    dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)",
-                                frameinfo.lineno + 1, frameinfo.filename)
-    event_mapping = {"dropped": dropped_event}
-    event_id_to_name = {dropped_event_id: "dropped"}
-
-    for event in events:
-        event_mapping[event.name] = event
+    Args:
+        events_fobj (file): file-object to read event data from
+        log_fobj (file): file-object to read log data from
+        analyzer_class (Analyzer): the Analyzer to interpret the event data
+        read_header (bool, optional): Whether to read header data from the log data. Defaults to True.
+    """
+    if read_header:
+        read_trace_header(log_fobj)
 
-    # If there is no header assume event ID mapping matches events list
-    if not read_header:
-        for event_id, event in enumerate(events):
-            event_id_to_name[event_id] = event.name
+    events = read_events(events_fobj, events_fobj.name)
 
     with analyzer_class() as analyzer:
-        for event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(event_mapping, event_id_to_name, log):
-            event = event_mapping[event_id]
+        for event, event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(events, log_fobj, read_header):
             fn = getattr(analyzer, event.name, analyzer.catchall)
             fn(*rec_args, event=event, event_id=event_id, timestamp_ns=timestamp_ns, pid=record_pid)
 
@@ -213,8 +210,7 @@ def run(analyzer):
         raise SimpleException(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
 
     with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj:
-        events = read_events(events_fobj, trace_event_path)
-        process(events, log_fobj, analyzer, read_header=not no_header)
+        process(events_fobj, log_fobj, analyzer, read_header=not no_header)
 
 if __name__ == '__main__':
     class Formatter(Analyzer):
-- 
2.38.1

[PATCH v2 10/12] MAINTAINERS: add maintainer of simpletrace.py

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

In my work to refactor simpletrace.py, I noticed that there's no
maintainer of it, and has the status of "odd fixes". I'm using it from
time to time, so I'd like to maintain the script.

I've added myself as reviewer under "Tracing" to be informed of changes
that might affect simpletrace.py.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 MAINTAINERS | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/MAINTAINERS b/MAINTAINERS
index 5340de0515..19edec5dda 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -3035,7 +3035,7 @@ R: Paolo Bonzini <pbonzini@redhat.com>
 R: Bandan Das <bsd@redhat.com>
 R: Stefan Hajnoczi <stefanha@redhat.com>
 R: Thomas Huth <thuth@redhat.com>
-R: Darren Kenny <darren.kenny@oracle.com> 
+R: Darren Kenny <darren.kenny@oracle.com>
 R: Qiuhao Li <Qiuhao.Li@outlook.com>
 S: Maintained
 F: tests/qtest/fuzz/
@@ -3076,6 +3076,7 @@ F: stubs/
 
 Tracing
 M: Stefan Hajnoczi <stefanha@redhat.com>
+R: Mads Ynddal <mads@ynddal.dk>
 S: Maintained
 F: trace/
 F: trace-events
@@ -3088,6 +3089,11 @@ F: docs/tools/qemu-trace-stap.rst
 F: docs/devel/tracing.rst
 T: git https://github.com/stefanha/qemu.git tracing
 
+Simpletrace
+M: Mads Ynddal <mads@ynddal.dk>
+S: Maintained
+F: scripts/simpletrace.py
+
 TPM
 M: Stefan Berger <stefanb@linux.ibm.com>
 S: Maintained
-- 
2.38.1

[PATCH v2 11/12] scripts/analyse-locks-simpletrace.py: changed iteritems() to items()

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

Python 3 removed `dict.iteritems()` in favor of `dict.items()`. This
means the script curerntly doesn't work on Python 3.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/analyse-locks-simpletrace.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/analyse-locks-simpletrace.py b/scripts/analyse-locks-simpletrace.py
index 63c11f4fce..d650dd7140 100755
--- a/scripts/analyse-locks-simpletrace.py
+++ b/scripts/analyse-locks-simpletrace.py
@@ -75,7 +75,7 @@ def get_args():
            (analyser.locks, analyser.locked, analyser.unlocks))
 
     # Now dump the individual lock stats
-    for key, val in sorted(analyser.mutex_records.iteritems(),
+    for key, val in sorted(analyser.mutex_records.items(),
                            key=lambda k_v: k_v[1]["locks"]):
         print ("Lock: %#x locks: %d, locked: %d, unlocked: %d" %
                (key, val["locks"], val["locked"], val["unlocked"]))
-- 
2.38.1

[PATCH v2 12/12] scripts/analyse-locks-simpletrace.py: reflect changes to process in simpletrace.py

[Mads Ynddal]

From: Mads Ynddal <m.ynddal@samsung.com>

The signature of `process` in simpletrace.py has changed to not take
filepaths as the two first arguments, but rather a file-like object. We
change the code here to reflect that.

Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
---
 scripts/analyse-locks-simpletrace.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/scripts/analyse-locks-simpletrace.py b/scripts/analyse-locks-simpletrace.py
index d650dd7140..235fae2ba2 100755
--- a/scripts/analyse-locks-simpletrace.py
+++ b/scripts/analyse-locks-simpletrace.py
@@ -69,7 +69,8 @@ def get_args():
 
     # Gather data from the trace
     analyser = MutexAnalyser()
-    simpletrace.process(args.events, args.tracefile, analyser)
+    with open(args.events, 'r') as events, open(args.tracefile, 'rb') as tracefile:
+        simpletrace.process(events, tracefile, analyser)
 
     print ("Total locks: %d, locked: %d, unlocked: %d" %
            (analyser.locks, analyser.locked, analyser.unlocks))
-- 
2.38.1

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[John Snow]

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

On Tue, May 2, 2023, 5:24 AM Mads Ynddal <mads@ynddal.dk> wrote:

> From: Mads Ynddal <m.ynddal@samsung.com>
>
> I wanted to use simpletrace.py for an internal project, so I tried to
> update
> and polish the code. Some of the commits resolve specific issues, while
> some
> are more subjective.
>
> I've tried to divide it into commits so we can discuss the
> individual changes, and I'm ready to pull things out, if it isn't needed.
>

Just a quick note to say that I'll be on and off the rest of this week, but
this is on my radar to look at soon.

A question for you: do you think it's possible to move simpletrace into
qemu/python/utils? This requires cleaning up the code to some fairly
pedantic standards, but helps protect it against rot as we change target
python versions.

No problem if that's too much to ask. just want to know if you had looked
into it.


> v2:
>  * Added myself as maintainer of simpletrace.py
>  * Improve docstring on `process`
>  * Changed call to `process` in scripts/analyse-locks-simpletrace.py to
> reflect new argument types
>  * Replaced `iteritems()` with `items()` in
> scripts/analyse-locks-simpletrace.py to support Python 3
>
> Mads Ynddal (12):
>   simpletrace: Improve parsing of sys.argv; fix files never closed.
>   simpletrace: Annotate magic constants from QEMU code
>   simpletrace: changed naming of edict and idtoname to improve
>     readability
>   simpletrace: update code for Python 3.11
>   simpletrace: Changed Analyzer class to become context-manager
>   simpletrace: Simplify construction of tracing methods
>   simpletrace: Improved error handling on struct unpack
>   simpletrace: define exception and add handling
>   simpletrace: Refactor to separate responsibilities
>   MAINTAINERS: add maintainer of simpletrace.py
>   scripts/analyse-locks-simpletrace.py: changed iteritems() to items()
>   scripts/analyse-locks-simpletrace.py: reflect changes to process in
>     simpletrace.py
>
>  MAINTAINERS                          |   8 +-
>  scripts/analyse-locks-simpletrace.py |   5 +-
>  scripts/simpletrace.py               | 307 ++++++++++++---------------
>  3 files changed, 150 insertions(+), 170 deletions(-)
>
> --
> 2.38.1
>
>
>

[-- Attachment #2: Type: text/html, Size: 3080 bytes --]

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:27AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> I wanted to use simpletrace.py for an internal project, so I tried to update
> and polish the code. Some of the commits resolve specific issues, while some
> are more subjective.

An internal project based on qemu.git or a completely separate codebase?

Sometimes I've wondered whether tracetool should be extracted from
qemu.git and moved into its own QEMU-independent place. That way other
C/C++ applications and libraries could use it easily.

Now that Alex Bennee removed the vcpu trace events that were specific to
QEMU, the tracing code is less tightly coupled to QEMU. There are
probably still a number of places that need to be cleaned up in order
for the tracing code to be independent of QEMU though.

If there is interest in doing this, I support the effort, although I'm
not sure how much time I have to actually do the work myself.

> 
> I've tried to divide it into commits so we can discuss the
> individual changes, and I'm ready to pull things out, if it isn't needed.
> 
> v2:
>  * Added myself as maintainer of simpletrace.py
>  * Improve docstring on `process`
>  * Changed call to `process` in scripts/analyse-locks-simpletrace.py to reflect new argument types
>  * Replaced `iteritems()` with `items()` in scripts/analyse-locks-simpletrace.py to support Python 3
> 
> Mads Ynddal (12):
>   simpletrace: Improve parsing of sys.argv; fix files never closed.
>   simpletrace: Annotate magic constants from QEMU code
>   simpletrace: changed naming of edict and idtoname to improve
>     readability
>   simpletrace: update code for Python 3.11
>   simpletrace: Changed Analyzer class to become context-manager
>   simpletrace: Simplify construction of tracing methods
>   simpletrace: Improved error handling on struct unpack
>   simpletrace: define exception and add handling
>   simpletrace: Refactor to separate responsibilities
>   MAINTAINERS: add maintainer of simpletrace.py
>   scripts/analyse-locks-simpletrace.py: changed iteritems() to items()
>   scripts/analyse-locks-simpletrace.py: reflect changes to process in
>     simpletrace.py
> 
>  MAINTAINERS                          |   8 +-
>  scripts/analyse-locks-simpletrace.py |   5 +-
>  scripts/simpletrace.py               | 307 ++++++++++++---------------
>  3 files changed, 150 insertions(+), 170 deletions(-)
> 
> -- 
> 2.38.1
> 

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

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[John Snow]

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

On Thu, May 4, 2023, 1:48 PM Stefan Hajnoczi <stefanha@redhat.com> wrote:

> On Tue, May 02, 2023 at 11:23:27AM +0200, Mads Ynddal wrote:
> > From: Mads Ynddal <m.ynddal@samsung.com>
> >
> > I wanted to use simpletrace.py for an internal project, so I tried to
> update
> > and polish the code. Some of the commits resolve specific issues, while
> some
> > are more subjective.
>
> An internal project based on qemu.git or a completely separate codebase?
>
> Sometimes I've wondered whether tracetool should be extracted from
> qemu.git and moved into its own QEMU-independent place. That way other
> C/C++ applications and libraries could use it easily.
>
> Now that Alex Bennee removed the vcpu trace events that were specific to
> QEMU, the tracing code is less tightly coupled to QEMU. There are
> probably still a number of places that need to be cleaned up in order
> for the tracing code to be independent of QEMU though.
>
> If there is interest in doing this, I support the effort, although I'm
> not sure how much time I have to actually do the work myself.
>

I meant internal, but if there's interest in fully extracting it, I have a
playbook for that now based on my efforts to do the same for qemu.qmp and I
can offer good stewardship for that process.

I only suggest moving it under python/ so that we have it type checked and
tested against python deprecations as part of CI as a preventative measure
against rot.

(Stuff in python/ is rigorously checked, stuff in scripts/ is not.)

--js


> >
> > I've tried to divide it into commits so we can discuss the
> > individual changes, and I'm ready to pull things out, if it isn't needed.
> >
> > v2:
> >  * Added myself as maintainer of simpletrace.py
> >  * Improve docstring on `process`
> >  * Changed call to `process` in scripts/analyse-locks-simpletrace.py to
> reflect new argument types
> >  * Replaced `iteritems()` with `items()` in
> scripts/analyse-locks-simpletrace.py to support Python 3
> >
> > Mads Ynddal (12):
> >   simpletrace: Improve parsing of sys.argv; fix files never closed.
> >   simpletrace: Annotate magic constants from QEMU code
> >   simpletrace: changed naming of edict and idtoname to improve
> >     readability
> >   simpletrace: update code for Python 3.11
> >   simpletrace: Changed Analyzer class to become context-manager
> >   simpletrace: Simplify construction of tracing methods
> >   simpletrace: Improved error handling on struct unpack
> >   simpletrace: define exception and add handling
> >   simpletrace: Refactor to separate responsibilities
> >   MAINTAINERS: add maintainer of simpletrace.py
> >   scripts/analyse-locks-simpletrace.py: changed iteritems() to items()
> >   scripts/analyse-locks-simpletrace.py: reflect changes to process in
> >     simpletrace.py
> >
> >  MAINTAINERS                          |   8 +-
> >  scripts/analyse-locks-simpletrace.py |   5 +-
> >  scripts/simpletrace.py               | 307 ++++++++++++---------------
> >  3 files changed, 150 insertions(+), 170 deletions(-)
> >
> > --
> > 2.38.1
> >
>

[-- Attachment #2: Type: text/html, Size: 4155 bytes --]

Re: [PATCH v2 01/12] simpletrace: Improve parsing of sys.argv; fix files never closed.

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:28AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> The arguments extracted from `sys.argv` named and unpacked to make it
> clear what the arguments are and what they're used for.
> 
> The two input files were opened, but never explicitly closed. File usage
> changed to use `with` statement to take care of this. At the same time,
> ownership of the file-object is moved up to `run` function. Secondary `open`
> inside `process` removed so there's only one place to handle `open`.
> 
> Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
> ---
>  scripts/simpletrace.py | 28 +++++++++++-----------------
>  1 file changed, 11 insertions(+), 17 deletions(-)
> 
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
> index 1f6d1ae1f3..9211caaec1 100755
> --- a/scripts/simpletrace.py
> +++ b/scripts/simpletrace.py
> @@ -9,6 +9,7 @@
>  #
>  # For help see docs/devel/tracing.rst
>  
> +import sys
>  import struct
>  import inspect
>  from tracetool import read_events, Event
> @@ -44,7 +45,6 @@ def get_record(edict, idtoname, rechdr, fobj):
>          try:
>              event = edict[name]
>          except KeyError as e:
> -            import sys
>              sys.stderr.write('%s event is logged but is not declared ' \
>                               'in the trace events file, try using ' \
>                               'trace-events-all instead.\n' % str(e))
> @@ -166,11 +166,6 @@ def end(self):
>  
>  def process(events, log, analyzer, read_header=True):
>      """Invoke an analyzer on each event in a log."""
> -    if isinstance(events, str):
> -        events = read_events(open(events, 'r'), events)
> -    if isinstance(log, str):
> -        log = open(log, 'rb')
> -
>      if read_header:
>          read_trace_header(log)

simpletrace.py is both a command-line tool and a Python module. The
Python module has a public API that people's scripts may rely on. Let's
avoid breaking API changes unless necessary so that existing scripts
that import simpletrace continue to work.

It's not very clear what is a public API in simpletrace.py, the file
should really have __all__ = ['Analyzer', 'process', 'run'].
Nevertheless, Analyzer's doc comments mention process() and the
process() function itself also has doc comments, so it's a public API.

Please drop this change to avoid breaking the public API.

>  
> @@ -223,19 +218,18 @@ def run(analyzer):
>  
>      This function is useful as a driver for simple analysis scripts.  More
>      advanced scripts will want to call process() instead."""
> -    import sys
> -
> -    read_header = True
> -    if len(sys.argv) == 4 and sys.argv[1] == '--no-header':
> -        read_header = False
> -        del sys.argv[1]
> -    elif len(sys.argv) != 3:
> -        sys.stderr.write('usage: %s [--no-header] <trace-events> ' \
> -                         '<trace-file>\n' % sys.argv[0])
> +
> +    try:
> +        # NOTE: See built-in `argparse` module for a more robust cli interface
> +        *no_header, trace_event_path, trace_file_path = sys.argv[1:]
> +        assert no_header == [] or no_header == ['--no-header'], 'Invalid no-header argument'
> +    except (AssertionError, ValueError):
> +        sys.stderr.write(f'usage: {sys.argv[0]} [--no-header] <trace-events> <trace-file>\n')
>          sys.exit(1)
>  
> -    events = read_events(open(sys.argv[1], 'r'), sys.argv[1])
> -    process(events, sys.argv[2], analyzer, read_header=read_header)
> +    with open(trace_event_path, 'r') as events_fobj, open(trace_file_path, 'rb') as log_fobj:
> +        events = read_events(events_fobj, trace_event_path)
> +        process(events, log_fobj, analyzer, read_header=not no_header)
>  
>  if __name__ == '__main__':
>      class Formatter(Analyzer):
> -- 
> 2.38.1
> 

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

Re: [PATCH v2 01/12] simpletrace: Improve parsing of sys.argv; fix files never closed.

[Mads Ynddal]

> simpletrace.py is both a command-line tool and a Python module. The
> Python module has a public API that people's scripts may rely on. Let's
> avoid breaking API changes unless necessary so that existing scripts
> that import simpletrace continue to work.
> 
> It's not very clear what is a public API in simpletrace.py, the file
> should really have __all__ = ['Analyzer', 'process', 'run'].
> Nevertheless, Analyzer's doc comments mention process() and the
> process() function itself also has doc comments, so it's a public API.
> 
> Please drop this change to avoid breaking the public API.

I agree, I'll revert the changes. I can add an `__all__` too.

I'd like to avoid having the same `open`, `read_trace_header` and `read_events`
multiple places. Would it be acceptable to let `process` be more of a stub and
move the logic to an internal `_process` function maybe?

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Mads Ynddal]

> A question for you: do you think it's possible to move simpletrace into qemu/python/utils? This requires cleaning up the code to some fairly pedantic standards, but helps protect it against rot as we change target python versions. 
> 
> No problem if that's too much to ask. just want to know if you had looked into it.

Potentially, this would be possible. But `simpletrace.py` imports
`qemu/scripts/tracetool/`, so that would have to be moved as well, or installed
as a package. I haven't touched the `tracetool` code itself, so I'm not sure how
feasible it is (i.e. how many other places use `tracetool`).

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Stefan Hajnoczi]

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

On Thu, May 04, 2023 at 01:53:38PM -0400, John Snow wrote:
> On Thu, May 4, 2023, 1:48 PM Stefan Hajnoczi <stefanha@redhat.com> wrote:
> 
> > On Tue, May 02, 2023 at 11:23:27AM +0200, Mads Ynddal wrote:
> > > From: Mads Ynddal <m.ynddal@samsung.com>
> > >
> > > I wanted to use simpletrace.py for an internal project, so I tried to
> > update
> > > and polish the code. Some of the commits resolve specific issues, while
> > some
> > > are more subjective.
> >
> > An internal project based on qemu.git or a completely separate codebase?
> >
> > Sometimes I've wondered whether tracetool should be extracted from
> > qemu.git and moved into its own QEMU-independent place. That way other
> > C/C++ applications and libraries could use it easily.
> >
> > Now that Alex Bennee removed the vcpu trace events that were specific to
> > QEMU, the tracing code is less tightly coupled to QEMU. There are
> > probably still a number of places that need to be cleaned up in order
> > for the tracing code to be independent of QEMU though.
> >
> > If there is interest in doing this, I support the effort, although I'm
> > not sure how much time I have to actually do the work myself.
> >
> 
> I meant internal, but if there's interest in fully extracting it, I have a
> playbook for that now based on my efforts to do the same for qemu.qmp and I
> can offer good stewardship for that process.

I was curious how Mads is using simpletrace for an internal (to
Samsung?) project.

Maybe only simpletrace.py is needed because Mads' own code emits trace
logs in the simpletrace binary format, but in the general case we could
extract most of QEMU's tracing infrastructure (including tracetool).

Stefan

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

Re: [PATCH v2 01/12] simpletrace: Improve parsing of sys.argv; fix files never closed.

[Stefan Hajnoczi]

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

On Mon, May 08, 2023 at 01:18:40PM +0000, Mads Ynddal wrote:
> > simpletrace.py is both a command-line tool and a Python module. The
> > Python module has a public API that people's scripts may rely on. Let's
> > avoid breaking API changes unless necessary so that existing scripts
> > that import simpletrace continue to work.
> > 
> > It's not very clear what is a public API in simpletrace.py, the file
> > should really have __all__ = ['Analyzer', 'process', 'run'].
> > Nevertheless, Analyzer's doc comments mention process() and the
> > process() function itself also has doc comments, so it's a public API.
> > 
> > Please drop this change to avoid breaking the public API.
> 
> I agree, I'll revert the changes. I can add an `__all__` too.
> 
> I'd like to avoid having the same `open`, `read_trace_header` and `read_events`
> multiple places. Would it be acceptable to let `process` be more of a stub and
> move the logic to an internal `_process` function maybe?

Yes, as long as the existing public API doesn't change that would be
fine.

Stefan

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

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Stefan Hajnoczi]

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

On Mon, May 08, 2023 at 03:28:04PM +0200, Mads Ynddal wrote:
> 
> > A question for you: do you think it's possible to move simpletrace into qemu/python/utils? This requires cleaning up the code to some fairly pedantic standards, but helps protect it against rot as we change target python versions. 
> > 
> > No problem if that's too much to ask. just want to know if you had looked into it.
> 
> Potentially, this would be possible. But `simpletrace.py` imports
> `qemu/scripts/tracetool/`, so that would have to be moved as well, or installed
> as a package. I haven't touched the `tracetool` code itself, so I'm not sure how
> feasible it is (i.e. how many other places use `tracetool`).

tracetool is only used by QEMU's build system to generate code from the
trace-events files. In theory it's possible to move it.

I'm not sure I understand the purpose of moving it to python/. What
infrastructure does python/ provide that's not available to
simpletrace.py in its current location?

Stefan

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

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Mads Ynddal]

> 
> I was curious how Mads is using simpletrace for an internal (to
> Samsung?) project.
> 

I was just tracing the NVMe emulation to get some metrics. The code is all
upstream or a part of this patchset. The rest is tracing configs.

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[Stefan Hajnoczi]

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

On Mon, May 08, 2023 at 06:50:58PM +0200, Mads Ynddal wrote:
> 
> > 
> > I was curious how Mads is using simpletrace for an internal (to
> > Samsung?) project.
> > 
> 
> I was just tracing the NVMe emulation to get some metrics. The code is all
> upstream or a part of this patchset. The rest is tracing configs.

I see, not a different codebase from QEMU. In that case what I said
about extracting tracetool and simpletrace from qemu.git won't be
useful.

Stefan

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

Re: [PATCH v2 02/12] simpletrace: Annotate magic constants from QEMU code

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:29AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> It wasn't clear where the constants and structs came from, so I added
> comments to help.
> 
> Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
> ---
>  scripts/simpletrace.py | 14 +++++++-------
>  1 file changed, 7 insertions(+), 7 deletions(-)
> 
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
> index 9211caaec1..7ba805443d 100755
> --- a/scripts/simpletrace.py
> +++ b/scripts/simpletrace.py
> @@ -15,15 +15,15 @@
>  from tracetool import read_events, Event
>  from tracetool.backend.simple import is_string
>  
> -header_event_id = 0xffffffffffffffff
> -header_magic    = 0xf2b177cb0aa429b4
> -dropped_event_id = 0xfffffffffffffffe
> +header_event_id = 0xffffffffffffffff # trace/simple.c::HEADER_EVENT_ID
> +header_magic    = 0xf2b177cb0aa429b4 # trace/simple.c::HEADER_MAGIC
> +dropped_event_id = 0xfffffffffffffffe # trace/simple.c::DROPPED_EVENT_ID
>  
> -record_type_mapping = 0
> -record_type_event = 1
> +record_type_mapping = 0 # trace/simple.c::TRACE_RECORD_TYPE_MAPPING
> +record_type_event = 1 # trace/simple.c::TRACE_RECORD_TYPE_EVENT
>  
> -log_header_fmt = '=QQQ'
> -rec_header_fmt = '=QQII'
> +log_header_fmt = '=QQQ' # trace/simple.c::TraceLogHeader
> +rec_header_fmt = '=QQII' # trace/simple.c::TraceRecord

From my reply to v1 of this patch series:

This is fragile since this information will be outdated if the C source
code changes (e.g. renaming files or variables).

Instead I would add the following comment:

  # This is the binary format that the QEMU "simple" trace backend
  # emits. There is no specification documentation because the format is
  # not guaranteed to be stable. Trace files must be parsed with the
  # same trace-events-all file and the same simpletrace.py file that
  # QEMU was built with.

I hope that clarifies the scope of the binary format and someone wishing
to look into the format would then know to look at the "simple" trace
backend.

Stefan

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

Re: [PATCH v2 03/12] simpletrace: changed naming of edict and idtoname to improve readability

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:30AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> Readability is subjective, but I've expanded the naming of the variables
> and arguments, to help with understanding for new eyes on the code.
> 
> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
> Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
> ---
>  scripts/simpletrace.py | 34 +++++++++++++++++-----------------
>  1 file changed, 17 insertions(+), 17 deletions(-)

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

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

Re: [PATCH v2 04/12] simpletrace: update code for Python 3.11

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:31AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> The call to `getargspec` was deprecated and in Python 3.11 it has been
> removed in favor of `getfullargspec`.

Please add that getfullargspec() is available in Python 3.6, the minimum
Python version required by QEMU.

That makes it clear that its safe to merge this patch.

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

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

Re: [PATCH v2 05/12] simpletrace: Changed Analyzer class to become context-manager

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:32AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> Instead of explicitly calling `begin` and `end`, we can change the class
> to use the context-manager paradigm. This is mostly a styling choice,
> used in modern Python code. But it also allows for more advanced analyzers
> to handle exceptions gracefully in the `__exit__` method (not
> demonstrated here).
> 
> Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
> ---
>  scripts/simpletrace.py | 40 +++++++++++++++++++++++-----------------
>  1 file changed, 23 insertions(+), 17 deletions(-)
> 
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
> index 7444a6e090..10ca093046 100755
> --- a/scripts/simpletrace.py
> +++ b/scripts/simpletrace.py
> @@ -121,12 +121,12 @@ def read_trace_records(event_mapping, event_id_to_name, fobj):
>  
>              yield rec
>  
> -class Analyzer(object):
> +class Analyzer:
>      """A trace file analyzer which processes trace records.
>  
> -    An analyzer can be passed to run() or process().  The begin() method is
> -    invoked, then each trace record is processed, and finally the end() method
> -    is invoked.
> +    An analyzer can be passed to run() or process().  The __enter__() method is
> +    invoked when opening the analyzer using the `with` statement, then each trace
> +    record is processed, and finally the __exit__() method is invoked.

Bearing in mind compatibility with existing simpletrace analysis
scripts, how about the following default method implementations?

  def __enter__(self):
      self.begin()

  def __exit__(self, exc_type, exc_val, exc_tb):
      if exc_type is None:
          self.end()
      return False

Now simpletrace.py can switch to using the context manager and new
scripts can implement __enter__()/__exit__(), while old scripts continue
to work.

>  
>      If a method matching a trace event name exists, it is invoked to process
>      that trace record.  Otherwise the catchall() method is invoked.
> @@ -152,19 +152,25 @@ def runstate_set(self, timestamp, pid, new_state):
>            ...
>      """
>  
> -    def begin(self):
> +    def __enter__(self):
>          """Called at the start of the trace."""
> -        pass
> +        return self
>  
>      def catchall(self, event, rec):
>          """Called if no specific method for processing a trace event has been found."""
>          pass
>  
> -    def end(self):
> +    def __exit__(self, _type, value, traceback):
>          """Called at the end of the trace."""
>          pass
>  
> -def process(events, log, analyzer, read_header=True):
> +    def __call__(self):
> +        """Fix for legacy use without context manager.
> +        We call the provided object in `process` regardless of it being the object-type or instance.
> +        With this function, it will work in both cases."""
> +        return self
> +
> +def process(events, log, analyzer_class, read_header=True):

Please don't change the function signature since this is a public method
and we should avoid breaking existing callers when possible.

Instead of:

  with analyzer_class() as analyzer:

we can use:

  with analyzer:
      ...

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

Re: [PATCH v2 06/12] simpletrace: Simplify construction of tracing methods

[Stefan Hajnoczi]

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

On Tue, May 02, 2023 at 11:23:33AM +0200, Mads Ynddal wrote:
> From: Mads Ynddal <m.ynddal@samsung.com>
> 
> By moving the dynamic argument construction to keyword-arguments,
> we can remove all of the specialized handling, and streamline it.
> If a tracing method wants to access these, they can define the
> kwargs, or ignore it be placing `**kwargs` at the end of the
> function's arguments list.
> 
> Signed-off-by: Mads Ynddal <m.ynddal@samsung.com>
> ---
>  scripts/simpletrace.py | 84 ++++++++++++++++--------------------------
>  1 file changed, 32 insertions(+), 52 deletions(-)

This is nice but breaking existing analysis scripts should be avoided.

I suggest preserving the Analyzer class the way it is and adding a new
Analyzer2 class that follows the new method signature for trace event
methods.

> 
> diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
> index 10ca093046..f6b40d56f6 100755
> --- a/scripts/simpletrace.py
> +++ b/scripts/simpletrace.py
> @@ -131,16 +131,25 @@ class Analyzer:
>      If a method matching a trace event name exists, it is invoked to process
>      that trace record.  Otherwise the catchall() method is invoked.
>  
> +    The methods are called with a set of keyword-arguments. These can be ignored
> +    using `**kwargs` or defined like any keyword-argument.
> +
> +    The following keyword-arguments are available:
> +        event: Event object of current trace
> +        event_id: The id of the event in the current trace file
> +        timestamp_ns: The timestamp in nanoseconds of the trace
> +        pid: The process id recorded for the given trace
> +
>      Example:
>      The following method handles the runstate_set(int new_state) trace event::
>  
> -      def runstate_set(self, new_state):
> +      def runstate_set(self, new_state, **kwargs):
>            ...
>  
> -    The method can also take a timestamp argument before the trace event
> -    arguments::
> +    The method can also explicitly take a timestamp keyword-argument with the
> +    trace event arguments::
>  
> -      def runstate_set(self, timestamp, new_state):
> +      def runstate_set(self, new_state, *, timestamp, **kwargs):
>            ...
>  
>      Timestamps have the uint64_t type and are in nanoseconds.
> @@ -148,7 +157,7 @@ def runstate_set(self, timestamp, new_state):
>      The pid can be included in addition to the timestamp and is useful when
>      dealing with traces from multiple processes::
>  
> -      def runstate_set(self, timestamp, pid, new_state):
> +      def runstate_set(self, new_state, *, timestamp, pid, **kwargs):
>            ...
>      """
>  
> @@ -156,7 +165,7 @@ def __enter__(self):
>          """Called at the start of the trace."""
>          return self
>  
> -    def catchall(self, event, rec):
> +    def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
>          """Called if no specific method for processing a trace event has been found."""
>          pass
>  
> @@ -189,34 +198,11 @@ def process(events, log, analyzer_class, read_header=True):
>          for event_id, event in enumerate(events):
>              event_id_to_name[event_id] = event.name
>  
> -    def build_fn(analyzer, event):
> -        if isinstance(event, str):
> -            return analyzer.catchall
> -
> -        fn = getattr(analyzer, event.name, None)
> -        if fn is None:
> -            return analyzer.catchall
> -
> -        event_argcount = len(event.args)
> -        fn_argcount = len(inspect.getfullargspec(fn)[0]) - 1
> -        if fn_argcount == event_argcount + 1:
> -            # Include timestamp as first argument
> -            return lambda _, rec: fn(*(rec[1:2] + rec[3:3 + event_argcount]))
> -        elif fn_argcount == event_argcount + 2:
> -            # Include timestamp and pid
> -            return lambda _, rec: fn(*rec[1:3 + event_argcount])
> -        else:
> -            # Just arguments, no timestamp or pid
> -            return lambda _, rec: fn(*rec[3:3 + event_argcount])
> -
>      with analyzer_class() as analyzer:
> -        fn_cache = {}
> -        for rec in read_trace_records(event_mapping, event_id_to_name, log):
> -            event_num = rec[0]
> -            event = event_mapping[event_num]
> -            if event_num not in fn_cache:
> -                fn_cache[event_num] = build_fn(analyzer, event)
> -            fn_cache[event_num](event, rec)
> +        for event_id, timestamp_ns, record_pid, *rec_args in read_trace_records(event_mapping, event_id_to_name, log):
> +            event = event_mapping[event_id]
> +            fn = getattr(analyzer, event.name, analyzer.catchall)
> +            fn(*rec_args, event=event, event_id=event_id, timestamp_ns=timestamp_ns, pid=record_pid)
>  
>  
>  def run(analyzer):
> @@ -240,24 +226,18 @@ def run(analyzer):
>  if __name__ == '__main__':
>      class Formatter(Analyzer):
>          def __init__(self):
> -            self.last_timestamp = None
> -
> -        def catchall(self, event, rec):
> -            timestamp = rec[1]
> -            if self.last_timestamp is None:
> -                self.last_timestamp = timestamp
> -            delta_ns = timestamp - self.last_timestamp
> -            self.last_timestamp = timestamp
> -
> -            fields = [event.name, '%0.3f' % (delta_ns / 1000.0),
> -                      'pid=%d' % rec[2]]
> -            i = 3
> -            for type, name in event.args:
> -                if is_string(type):
> -                    fields.append('%s=%s' % (name, rec[i]))
> -                else:
> -                    fields.append('%s=0x%x' % (name, rec[i]))
> -                i += 1
> -            print(' '.join(fields))
> +            self.last_timestamp_ns = None
> +
> +        def catchall(self, *rec_args, event, timestamp_ns, pid, event_id):
> +            if self.last_timestamp_ns is None:
> +                self.last_timestamp_ns = timestamp_ns
> +            delta_ns = timestamp_ns - self.last_timestamp_ns
> +            self.last_timestamp_ns = timestamp_ns
> +
> +            fields = [
> +                f'{name}={r}' if is_string(type) else f'{name}=0x{r:x}'
> +                for r, (type, name) in zip(rec_args, event.args)
> +            ]
> +            print(f'{event.name} {delta_ns / 1000:0.3f} {pid=} ' + ' '.join(fields))
>  
>      run(Formatter())
> -- 
> 2.38.1
> 

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

Re: [PATCH v2 00/12] simpletrace: refactor and general improvements

[John Snow]

On Mon, May 8, 2023 at 11:16 AM Stefan Hajnoczi <stefanha@redhat.com> wrote:
>
> On Mon, May 08, 2023 at 03:28:04PM +0200, Mads Ynddal wrote:
> >
> > > A question for you: do you think it's possible to move simpletrace into qemu/python/utils? This requires cleaning up the code to some fairly pedantic standards, but helps protect it against rot as we change target python versions.
> > >
> > > No problem if that's too much to ask. just want to know if you had looked into it.
> >
> > Potentially, this would be possible. But `simpletrace.py` imports
> > `qemu/scripts/tracetool/`, so that would have to be moved as well, or installed
> > as a package. I haven't touched the `tracetool` code itself, so I'm not sure how
> > feasible it is (i.e. how many other places use `tracetool`).
>
> tracetool is only used by QEMU's build system to generate code from the
> trace-events files. In theory it's possible to move it.
>
> I'm not sure I understand the purpose of moving it to python/. What
> infrastructure does python/ provide that's not available to
> simpletrace.py in its current location?
>
> Stefan

It's just directory-based:

python/qemu/ are formatted as packages, with python/qemu/util/ serving
as a package that houses a bag of scripts. You can install these
things as a package into a venv and use them anywhere.
code in python/ is checked with a linter, type checker, etc while code
in scripts/ is not. It isn't installed anywhere and you may or may not
have to carefully set up PYTHONPATH= or choose your CWD carefully to
get the imports correct.

Over time I want to move more python code over under python/ so it
gets checked with the robots. The best stuff to move is stuff with
imports and dependencies. Truly standalone scripts aren't as important
to move.

It's not important for today, so let's not worry about it for this series.

--js

Re: [PATCH v2 04/12] simpletrace: update code for Python 3.11

[Mads Ynddal]

> On 9 May 2023, at 16.38, Stefan Hajnoczi <stefanha@redhat.com> wrote:
> 
> On Tue, May 02, 2023 at 11:23:31AM +0200, Mads Ynddal wrote:
>> From: Mads Ynddal <m.ynddal@samsung.com>
>> 
>> The call to `getargspec` was deprecated and in Python 3.11 it has been
>> removed in favor of `getfullargspec`.
> 
> Please add that getfullargspec() is available in Python 3.6, the minimum
> Python version required by QEMU.
> 
> That makes it clear that its safe to merge this patch.
> 
> Otherwise:
> Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

I'll get this added.

Re: [PATCH v2 02/12] simpletrace: Annotate magic constants from QEMU code

[Mads Ynddal]

> 
> From my reply to v1 of this patch series:
> 
> This is fragile since this information will be outdated if the C source
> code changes (e.g. renaming files or variables).
> 
> Instead I would add the following comment:
> 
>  # This is the binary format that the QEMU "simple" trace backend
>  # emits. There is no specification documentation because the format is
>  # not guaranteed to be stable. Trace files must be parsed with the
>  # same trace-events-all file and the same simpletrace.py file that
>  # QEMU was built with.
> 
> I hope that clarifies the scope of the binary format and someone wishing
> to look into the format would then know to look at the "simple" trace
> backend.
> 
> Stefan


I must have missed that. I'll add this too.

Re: [PATCH v2 05/12] simpletrace: Changed Analyzer class to become context-manager

[Mads Ynddal]

> 
> Bearing in mind compatibility with existing simpletrace analysis
> scripts, how about the following default method implementations?
> 
>  def __enter__(self):
>      self.begin()
> 
>  def __exit__(self, exc_type, exc_val, exc_tb):
>      if exc_type is None:
>          self.end()
>      return False
> 
> Now simpletrace.py can switch to using the context manager and new
> scripts can implement __enter__()/__exit__(), while old scripts continue
> to work.

I was considering the same, but I was worried about double initialization if
someone used both the context manager as well as calling .begin(). Should we add
a guard, that prohibits this?

Otherwise, we could also keep begin()/end() in Analyzer, and then make Analyzer2
a context manager?

> 
> Please don't change the function signature since this is a public method
> and we should avoid breaking existing callers when possible.
> 
> Instead of:
> 
>  with analyzer_class() as analyzer:
> 
> we can use:
> 
>  with analyzer:
>      ...

I didn't think of that. Let's do this, if we keep the context manager.

Re: [PATCH v2 06/12] simpletrace: Simplify construction of tracing methods

[Mads Ynddal]

> 
> This is nice but breaking existing analysis scripts should be avoided.
> 
> I suggest preserving the Analyzer class the way it is and adding a new
> Analyzer2 class that follows the new method signature for trace event
> methods.

You're right. This has too large effects on the API.

I could go along with adding an Analyzer2 class. Should we mark Analyzer as
deprecated then? We could make __init__ emit a warning, and say new features are
only added to Analyzer2, but not put an exact EOL-date on Analyzer. I would
rather not maintain two parallel implementations of the same.

Let me know what you think.