[Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Stefan Hajnoczi]

The SystemTap flight recorder mode no longer works with simpletrace.stp because
the event ID mapping records are emitted the first time an event fires.
Chances are, the event ID mapping record will not be in ring buffer when the
users wants to print the trace.

This series solves the issue by using the trace-events-all global event
ordering for event IDs for simpletrace.stp.

Stefan Hajnoczi (2):
  trace: use static event ID mapping in simpletrace.stp
  simpletrace: fix flight recorder --no-header option

 scripts/simpletrace.py                       | 24 ++++++++++++++-----
 scripts/tracetool/format/simpletrace_stap.py | 36 ++++++++++++----------------
 2 files changed, 33 insertions(+), 27 deletions(-)

-- 
2.13.4

[Qemu-devel] [PATCH for-2.10 1/2] trace: use static event ID mapping in simpletrace.stp

[Stefan Hajnoczi]

Commit 7f1b588f20d027730676e627713ae3bbf6baab04 ("trace: emit name <->
ID mapping in simpletrace header") broke the SystemTap flight recorder
because event mapping records may no longer be present in the ring
buffer when the trace is analyzed.  This means simpletrace.py
--no-header does not know the event ID mapping needed to pretty-print
the trace.

Instead of numbering events dynamically, use a static event ID mapping
as dictated by the event order in the trace-events-all file.

The simpletrace.py script also uses trace-events-all so the next patch
will fix the simpletrace.py --no-header option to take advantage of this
knowledge.

Cc: Daniel P. Berrange <berrange@redhat.com>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/format/simpletrace_stap.py | 36 ++++++++++++----------------
 1 file changed, 15 insertions(+), 21 deletions(-)

diff --git a/scripts/tracetool/format/simpletrace_stap.py b/scripts/tracetool/format/simpletrace_stap.py
index 144b704bcd..6cfdc32867 100644
--- a/scripts/tracetool/format/simpletrace_stap.py
+++ b/scripts/tracetool/format/simpletrace_stap.py
@@ -22,33 +22,18 @@ def global_var_name(name):
     return probeprefix().replace(".", "_") + "_" + name
 
 def generate(events, backend, group):
-    id_map = global_var_name("event_name_to_id_map")
-    next_id = global_var_name("event_next_id")
-    map_func = global_var_name("simple_trace_map_event")
+    id_map = global_var_name("id_map")
+
     out('/* This file is autogenerated by tracetool, do not edit. */',
         '',
         'global %(id_map)s',
-        'global %(next_id)s',
-        'function %(map_func)s(name)',
         '',
-        '{',
-        '    if (!([name] in %(id_map)s)) {',
-        '        %(id_map)s[name] = %(next_id)s',
-        '        name_len = strlen(name)',
-        '        printf("%%8b%%8b%%4b%%.*s", 0, ',
-        '               %(next_id)s, name_len, name_len, name)',
-        '        %(next_id)s = %(next_id)s + 1',
-        '    }',
-        '    return %(id_map)s[name]',
-        '}',
         'probe begin',
         '{',
         '    printf("%%8b%%8b%%8b", 0xffffffffffffffff, 0xf2b177cb0aa429b4, 4)',
         '}',
         '',
-        id_map=id_map,
-        next_id=next_id,
-        map_func=map_func)
+        id_map=id_map)
 
     for event_id, e in enumerate(events):
         if 'disable' in e.properties:
@@ -56,11 +41,20 @@ def generate(events, backend, group):
 
         out('probe %(probeprefix)s.simpletrace.%(name)s = %(probeprefix)s.%(name)s ?',
             '{',
-            '    id = %(map_func)s("%(name)s")',
             probeprefix=probeprefix(),
-            map_func=map_func,
             name=e.name)
 
+        out('    if (!(["%(name)s"] in %(id_map)s)) {',
+            '        %(id_map)s["%(name)s"] = 1',
+            '        printf("%%8b%%8b%%4b%%.*s", 0, ',
+            '               %(event_id)s, %(name_len)s, %(name_len)s,',
+            '               "%(name)s")',
+            '    }',
+            id_map=id_map,
+            name=e.name,
+            name_len=len(e.name),
+            event_id=event_id)
+
         # Calculate record size
         sizes = ['24'] # sizeof(TraceRecord)
         for type_, name in e.args:
@@ -77,7 +71,7 @@ def generate(events, backend, group):
         sizestr = ' + '.join(sizes)
 
         # Generate format string and value pairs for record header and arguments
-        fields = [('8b', 'id'),
+        fields = [('8b', str(event_id)),
                   ('8b', 'gettimeofday_ns()'),
                   ('4b', sizestr),
                   ('4b', 'pid()')]
-- 
2.13.4

[Qemu-devel] [PATCH for-2.10 2/2] simpletrace: fix flight recorder --no-header option

[Stefan Hajnoczi]

The simpletrace.py script can pretty-print flight recorder ring buffers.
These are not full simpletrace binary trace files but just the end of a
trace file.  There is no header and the event ID mapping information is
often unavailable since the ring buffer may have filled up and discarded
event ID mapping records.

The simpletrace.stp script that generates ring buffer traces uses the
same trace-events-all input file as simpletrace.py.  Therefore both
scripts have the same global ordering of trace events.  A dynamic event
ID mapping isn't necessary: just use the trace-events-all file as the
reference for how event IDs are numbered.

It is now possible to analyze simpletrace.stp ring buffers again using:

  $ ./simpletrace.py trace-events-all path/to/ring-buffer

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/simpletrace.py | 24 ++++++++++++++++++------
 1 file changed, 18 insertions(+), 6 deletions(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 2a977e2ab9..a3a6315055 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -97,11 +97,17 @@ def read_trace_header(fobj):
         raise ValueError('Log format %d not supported with this QEMU release!'
                          % log_version)
 
-def read_trace_records(edict, fobj):
-    """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6)."""
-    idtoname = {
-        dropped_event_id: "dropped"
-    }
+def read_trace_records(edict, idtoname, 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.
+
+    Args:
+        edict (str -> Event): events dict, indexed by name
+        idtoname (int -> str): event names dict, indexed by event ID
+        fobj (file): input file
+
+    """
     while True:
         t = fobj.read(8)
         if len(t) == 0:
@@ -171,10 +177,16 @@ def process(events, log, analyzer, read_header=True):
 
     dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
     edict = {"dropped": dropped_event}
+    idtoname = {dropped_event_id: "dropped"}
 
     for event in events:
         edict[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
+
     def build_fn(analyzer, event):
         if isinstance(event, str):
             return analyzer.catchall
@@ -197,7 +209,7 @@ def process(events, log, analyzer, read_header=True):
 
     analyzer.begin()
     fn_cache = {}
-    for rec in read_trace_records(edict, log):
+    for rec in read_trace_records(edict, idtoname, log):
         event_num = rec[0]
         event = edict[event_num]
         if event_num not in fn_cache:
-- 
2.13.4

Re: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Daniel P. Berrange]

On Mon, Aug 14, 2017 at 05:21:40PM +0100, Stefan Hajnoczi wrote:
> The SystemTap flight recorder mode no longer works with simpletrace.stp because
> the event ID mapping records are emitted the first time an event fires.
> Chances are, the event ID mapping record will not be in ring buffer when the
> users wants to print the trace.
> 
> This series solves the issue by using the trace-events-all global event
> ordering for event IDs for simpletrace.stp.

I see the way you've written it means it'll still honour the event
id mappings in the header, if present, but I wonder what's the point
of keeping that anymore ? If we need to support this ring-buffer mode,
there's no way we can take advantage of having the ID mappings dynamically
defined - we must always guarantee a stable mapping.

IOW, should we just revert

  commit 7f1b588f20d027730676e627713ae3bbf6baab04
  Author: Daniel P. Berrange <berrange@redhat.com>
  Date:   Tue Oct 4 14:35:50 2016 +0100

    trace: emit name <-> ID mapping in simpletrace header
    
entirely ?


Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[no-reply]

Hi,

This series seems to have some coding style problems. See output below for
more information:

Message-id: 20170814162142.29666-1-stefanha@redhat.com
Subject: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode
Type: series

=== TEST SCRIPT BEGIN ===
#!/bin/bash

BASE=base
n=1
total=$(git log --oneline $BASE.. | wc -l)
failed=0

git config --local diff.renamelimit 0
git config --local diff.renames True

commits="$(git log --format=%H --reverse $BASE..)"
for c in $commits; do
    echo "Checking PATCH $n/$total: $(git log -n 1 --format=%s $c)..."
    if ! git show $c --format=email | ./scripts/checkpatch.pl --mailback -; then
        failed=1
        echo
    fi
    n=$((n+1))
done

exit $failed
=== TEST SCRIPT END ===

Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384
From https://github.com/patchew-project/qemu
 * [new tag]               patchew/20170814164002.23982-1-brijesh.singh@amd.com -> patchew/20170814164002.23982-1-brijesh.singh@amd.com
Switched to a new branch 'test'
45e9c56a4f simpletrace: fix flight recorder --no-header option
192d4fc2bc trace: use static event ID mapping in simpletrace.stp

=== OUTPUT BEGIN ===
Checking PATCH 1/2: trace: use static event ID mapping in simpletrace.stp...
Checking PATCH 2/2: simpletrace: fix flight recorder --no-header option...
ERROR: line over 90 characters
#39: FILE: scripts/simpletrace.py:101:
+    """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).

total: 1 errors, 0 warnings, 46 lines checked

Your patch has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.

=== OUTPUT END ===

Test command exited with code: 1


---
Email generated automatically by Patchew [http://patchew.org/].
Please send your feedback to patchew-devel@freelists.org

Re: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Stefan Hajnoczi]

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

On Mon, Aug 14, 2017 at 05:39:08PM +0100, Daniel P. Berrange wrote:
> On Mon, Aug 14, 2017 at 05:21:40PM +0100, Stefan Hajnoczi wrote:
> > The SystemTap flight recorder mode no longer works with simpletrace.stp because
> > the event ID mapping records are emitted the first time an event fires.
> > Chances are, the event ID mapping record will not be in ring buffer when the
> > users wants to print the trace.
> > 
> > This series solves the issue by using the trace-events-all global event
> > ordering for event IDs for simpletrace.stp.
> 
> I see the way you've written it means it'll still honour the event
> id mappings in the header, if present, but I wonder what's the point
> of keeping that anymore ? If we need to support this ring-buffer mode,
> there's no way we can take advantage of having the ID mappings dynamically
> defined - we must always guarantee a stable mapping.
> 
> IOW, should we just revert
> 
>   commit 7f1b588f20d027730676e627713ae3bbf6baab04
>   Author: Daniel P. Berrange <berrange@redhat.com>
>   Date:   Tue Oct 4 14:35:50 2016 +0100
> 
>     trace: emit name <-> ID mapping in simpletrace header
>     
> entirely ?

We cannot revert the commit because QEMU dynamically assigns event IDs
on startup.  Event IDs are not known ahead of time when the 'simple'
tracer is used.

Event IDs are only static when simpletrace.stp is used with the 'dtrace'
tracer since simpletrace.stp has global knowledge of all trace events
ahead of time.

Stefan

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

Re: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Stefan Hajnoczi]

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

On Mon, Aug 14, 2017 at 09:45:19AM -0700, no-reply@patchew.org wrote:
> === OUTPUT BEGIN ===
> Checking PATCH 1/2: trace: use static event ID mapping in simpletrace.stp...
> Checking PATCH 2/2: simpletrace: fix flight recorder --no-header option...
> ERROR: line over 90 characters
> #39: FILE: scripts/simpletrace.py:101:
> +    """Deserialize trace records from a file, yielding record tuples (event_num, timestamp, pid, arg1, ..., arg6).

This line was not changed by this patch.

Stefan

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

Re: [Qemu-devel] [PATCH for-2.10 0/2] trace: fix simpletrace.stp flight recorder mode

[Stefan Hajnoczi]

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

On Mon, Aug 14, 2017 at 05:39:08PM +0100, Daniel P. Berrange wrote:
> On Mon, Aug 14, 2017 at 05:21:40PM +0100, Stefan Hajnoczi wrote:
> > The SystemTap flight recorder mode no longer works with simpletrace.stp because
> > the event ID mapping records are emitted the first time an event fires.
> > Chances are, the event ID mapping record will not be in ring buffer when the
> > users wants to print the trace.
> > 
> > This series solves the issue by using the trace-events-all global event
> > ordering for event IDs for simpletrace.stp.
> 
> I see the way you've written it means it'll still honour the event
> id mappings in the header, if present, but I wonder what's the point
> of keeping that anymore ? If we need to support this ring-buffer mode,
> there's no way we can take advantage of having the ID mappings dynamically
> defined - we must always guarantee a stable mapping.
> 
> IOW, should we just revert
> 
>   commit 7f1b588f20d027730676e627713ae3bbf6baab04
>   Author: Daniel P. Berrange <berrange@redhat.com>
>   Date:   Tue Oct 4 14:35:50 2016 +0100
> 
>     trace: emit name <-> ID mapping in simpletrace header
>     
> entirely ?

Follow-up to my reply:

We can revert just the changes to simpletrace_stap.py.  This means:

1. Event ID mapping records are no longer emitted.
2. No simpletrace file header is emitted.

I like this idea because it's simpler than my current patch.  Users will
have to use the ./simpletrace.py --no-header option again when printing
simpletrace.stp traces, but that isn't a problem.

Stefan

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