Bug 1463172 - [Tracing] capturing trace data failed
Summary: [Tracing] capturing trace data failed
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: qemu-kvm-rhev
Version: 7.4
Hardware: Unspecified
OS: Unspecified
Target Milestone: rc
: ---
Assignee: Stefan Hajnoczi
QA Contact: jingzhao
Keywords: Regression
Depends On:
Blocks: 1482515 1482516
TreeView+ depends on / blocked
Reported: 2017-06-20 10:05 UTC by jingzhao
Modified: 2018-04-11 00:28 UTC (History)
8 users (show)

Clone Of:
: 1482515 1482516 (view as bug list)
Last Closed: 2018-04-11 00:26:27 UTC

Attachments (Terms of Use)

External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2018:1104 None None None 2018-04-11 00:28 UTC

Description jingzhao 2017-06-20 10:05:02 UTC
Description of problem:
capturing trace data failed when executed "/usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events-all /tmp/trace.log"

Version-Release number of selected component (if applicable):
[root@localhost ~]# rpm -qa | grep kernel-devel
[root@localhost ~]# uname -r
[root@localhost ~]# rpm -q systemtap
[root@localhost ~]# rpm -q qemu-kvm-rhev

How reproducible:

Steps to Reproduce:
1. cp /usr/share/qemu-kvm/systemtap/script.d/qemu_kvm.stp /etc/systemtap/script.d/

2. cp /usr/share/qemu-kvm/systemtap/conf.d/qemu_kvm.conf /etc/systemtap/conf.d/

3. service systemtap start qemu_kvm

4. [root@localhost home]# chkconfig systemtap on
[root@localhost home]# service systemtap status qemu_kvm
qemu_kvm is running...

5. boot guest with qemu command line [1]

6. staprun -A qemu_kvm >/tmp/trace.log 

7. In guest "dd if=/dev/zero of=/home/test.txt bs=1M count=1000"

8.[root@localhost ~]# /usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events-all /tmp/trace.log 

Actual results:
[root@localhost ~]# /usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events-all /tmp/trace.log 
Traceback (most recent call last):
  File "/usr/share/qemu-kvm/simpletrace.py", line 221, in <module>
  File "/usr/share/qemu-kvm/simpletrace.py", line 196, in run
    process(events, sys.argv[2], analyzer, read_header=read_header)
  File "/usr/share/qemu-kvm/simpletrace.py", line 171, in process
    for rec in read_trace_records(edict, log):
  File "/usr/share/qemu-kvm/simpletrace.py", line 107, in read_trace_records
    rec = read_record(edict, idtoname, fobj)
  File "/usr/share/qemu-kvm/simpletrace.py", line 71, in read_record
    return get_record(edict, idtoname, rechdr, fobj)
  File "/usr/share/qemu-kvm/simpletrace.py", line 43, in get_record
    name = idtoname[event_id]
KeyError: 17487890541996943796L

Expected results:
Capturing trace log correctly 

Additional info:

Tried with qemu-kvm-rhev-2.6.0-28.el7_3.10.x86_64 and didn't hit the error message, the result are following 
[root@localhost ~]# /usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events /tmp/trace.log 
monitor_protocol_event_queue 0.000 pid=18370 event=0x15 qdict=0x55f8a8530800 rate=0x0
monitor_protocol_event_emit 11.857 pid=18370 event=0x15 data=0x55f8a8530800
monitor_protocol_event_queue 7273950.737 pid=18370 event=0x1f qdict=0x55f8a9dde000 rate=0x0
monitor_protocol_event_emit 1.931 pid=18370 event=0x1f data=0x55f8a9dde000
monitor_protocol_event_queue 11065.735 pid=18370 event=0x21 qdict=0x55f8a9dde000 rate=0x0
monitor_protocol_event_emit 1.229 pid=18370 event=0x21 data=0x55f8a9dde000
monitor_protocol_event_queue 17506815.071 pid=18370 event=0x10 qdict=0x55f8a9826800 rate=0x0
monitor_protocol_event_emit 2.373 pid=18370 event=0x10 data=0x55f8a9826800

[1]/usr/libexec/qemu-kvm \
-machine q35,smm=on,accel=kvm \
-cpu Haswell-noTSX \
-nodefaults -rtc base=utc \
-m 4G \
-smp 4,sockets=4,cores=1,threads=1 \
-enable-kvm \
-uuid 990ea161-6b67-47b2-b803-19fb01d30d12 \
-k en-us \
-nodefaults \
-serial unix:/tmp/console,server,nowait \
-boot menu=on \
-qmp tcp:0:6667,server,nowait \
-vga qxl \
-chardev file,path=/home/seabios.log,id=seabios -device isa-debugcon,chardev=seabios,iobase=0x402 \
-device ioh3420,bus=pcie.0,id=root3 \
-drive file=/home/test/rhel/rhel74.qcow2,if=none,id=drive-virtio-disk0,format=qcow2,cache=none,werror=stop,rerror=stop \
-device virtio-blk-pci,drive=drive-virtio-disk0,id=virtio-disk0,bus=root3,bootindex=0 \
-device ioh3420,bus=pcie.0,id=root0,multifunction=on,chassis=1,addr=0xa.0 \
-device virtio-net-pci,netdev=tap10,mac=9a:6a:6b:6c:6d:6e,bus=root0 -netdev tap,id=tap10 \
-device ioh3420,bus=pcie.0,id=root1,chassis=11,addr=0xa.1 \
-device ioh3420,bus=pcie.0,id=root2,chassis=12,addr=0xa.2 \
-drive file=/home/test/rhel/block1.qcow2,if=none,id=drive-virtio-disk1,format=qcow2,cache=none,werror=stop,rerror=stop \
-device virtio-blk-pci,drive=drive-virtio-disk1,id=virtio-disk1,bus=root2 \
-monitor stdio \
-vnc :1 \

Comment 4 Stefan Hajnoczi 2017-06-21 13:21:30 UTC
QEMU uses the new simpletrace v4 format since commit 7f1b588f.  The simpletrace.py script was only partially extended to support v4 and the result is that the .stp script does not produce ringbuffer-friendly output anymore.

I'll need to investigate whether to stick to v3 for simpletrace.stp or if we can make it ringbuffer-friendly.

Comment 7 Stefan Hajnoczi 2017-08-14 16:30:47 UTC
Patch posted upstream for QEMU 2.10:

Comment 8 Stefan Hajnoczi 2017-08-16 11:54:28 UTC
Patches posted on rhvirt-patches.

Comment 10 Oneata Mircea Teodor 2017-08-17 13:03:28 UTC
This bug has been copied as 7.4 z-stream (EUS) bug #1482516 and now must be
resolved in the current update release, set blocker flag.

Comment 11 Stefan Hajnoczi 2017-10-05 20:26:32 UTC
The following commits came into qemu-kvm-rhev-2.10.0-1.el7 via the QEMU 2.10 rebase:

840d835177 simpletrace: fix flight recorder --no-header option
d6b76d6805 trace: use static event ID mapping in simpletrace.stp

Comment 13 jingzhao 2017-10-18 05:29:30 UTC
Verified it with qemu-kvm-rhev-2.10.0-2.el7.x86_64.

Tested Result:
[root@localhost ~]# /usr/share/qemu-kvm/simpletrace.py --no-header /usr/share/qemu-kvm/trace-events-all /tmp/trace.log 
monitor_protocol_event_queue 0.000 pid=2897 event=0x10 qdict=0x562cd3fa3600 rate=0x0
monitor_protocol_event_emit 2.484 pid=2897 event=0x10 data=0x562cd3fa3600
monitor_protocol_event_queue 34651065.642 pid=2897 event=0x1f qdict=0x562cd3fa3600 rate=0x0
monitor_protocol_event_emit 2.062 pid=2897 event=0x1f data=0x562cd3fa3600
monitor_protocol_event_queue 6309.118 pid=2897 event=0x21 qdict=0x562cd3fa3600 rate=0x0
monitor_protocol_event_emit 2.211 pid=2897 event=0x21 data=0x562cd3fa3600

Changed to verified according to the test result.

Comment 15 errata-xmlrpc 2018-04-11 00:26:27 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.