qemu/ftrace question

qemu/ftrace question

[Prasun Ratn]

Hi

I am trying to get qemu events using ftrace but not seeing any events in the
ftrace logs. I see kvm logs like the following but no qemu events such as virtio
blk events. I'm using a locally compiled qemu version with ftrace
backend enabled.

[001] d...  9290.926939: kvm_exit: reason HLT rip 0xffffffff81058e95 info 0 0

This is how I am enabling ftrace logs:

    echo 1 >/sys/kernel/debug/tracing/events/kvm/enable
    echo 1 > /sys/kernel/debug/tracing/tracing_on

    # run cmd
    $CMD

    # disable trace
    echo 0 >/sys/kernel/debug/tracing/events/kvm/enable
    echo 0 > /sys/kernel/debug/tracing/tracing_on

    # copy trace
    echo Copying trace to $outfile
    cp /sys/kernel/debug/tracing/trace $outfile

To debug, I build qemu with the 'log' backend, and I am able to see the
appropriate events in /var/log/libvirt log files.

However if I rebuild qemu with ftrace backend, I don't see any events. Do I need
to enable any other tracing events in /sys/kernel/debug/tracing? Do I need to
run any qemu monitor cmds?

Any thing obvious I may be missing? Any debug steps recommended?

I also tried using the simpletrace backend, but I am not sure where the trace
files are created. I am using libvirt and /proc for the qemu process shows the
cwd as '/' - I'm not sure what's supposed to happen here. Is it possible to
collect simpletrace traces using libvirt?

Thanks
Prasun

Re: qemu/ftrace question

[Stefan Hajnoczi]

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

On Tue, Jun 20, 2017 at 10:12:14PM +0530, Prasun Ratn wrote:
> I am trying to get qemu events using ftrace but not seeing any events in the
> ftrace logs. I see kvm logs like the following but no qemu events such as virtio
> blk events. I'm using a locally compiled qemu version with ftrace
> backend enabled.
> 
> [001] d...  9290.926939: kvm_exit: reason HLT rip 0xffffffff81058e95 info 0 0
> 
> This is how I am enabling ftrace logs:
> 
>     echo 1 >/sys/kernel/debug/tracing/events/kvm/enable
>     echo 1 > /sys/kernel/debug/tracing/tracing_on
> 
>     # run cmd
>     $CMD

Please post the command-line.  You need to enable the events you are
interested in.  Either use the -trace option or via the HMP monitor
(trace-event NAME on|off)/QMP monitor (trace-event-set-state).

> 
>     # disable trace
>     echo 0 >/sys/kernel/debug/tracing/events/kvm/enable
>     echo 0 > /sys/kernel/debug/tracing/tracing_on
> 
>     # copy trace
>     echo Copying trace to $outfile
>     cp /sys/kernel/debug/tracing/trace $outfile
> 
> To debug, I build qemu with the 'log' backend, and I am able to see the
> appropriate events in /var/log/libvirt log files.
> 
> However if I rebuild qemu with ftrace backend, I don't see any events. Do I need
> to enable any other tracing events in /sys/kernel/debug/tracing? Do I need to
> run any qemu monitor cmds?
> 
> Any thing obvious I may be missing? Any debug steps recommended?

Did you strace -f QEMU to see if there are writes to the trace_marker
file?

If you see the write() syscalls then you need to double-check your
commands to set up and access /sys/kernel/debug/tracing.

If you do not see the write() syscalls then you need to check that you
build QEMU with the ftrace backend and enabled the trace events you are
interested in.

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

Re: qemu/ftrace question

[Prasun Ratn]

>
> Please post the command-line.  You need to enable the events you are
> interested in.  Either use the -trace option or via the HMP monitor
> (trace-event NAME on|off)/QMP monitor (trace-event-set-state).
>

Posted below. Note that I used the same libvirtd xml with both log and ftrace
backends - and I see the events when using log backend.

>
> Did you strace -f QEMU to see if there are writes to the trace_marker
> file?
>
> If you see the write() syscalls then you need to double-check your
> commands to set up and access /sys/kernel/debug/tracing.
>
> If you do not see the write() syscalls then you need to check that you
> build QEMU with the ftrace backend and enabled the trace events you are
> interested in.

Thanks for your suggestion of using strace.

I see writes to fd 2 and 8:-

    sudo strace -f -p `pidof qemu-system-x86_64` -e write 2>strace.out

    $ wc -l strace.out
    2117 strace.out

    $ head strace.out
    Process 8988 attached with 4 threads
    [pid 24956] +++ exited with 0 +++
    [pid  9005] write(2, "8988@1498054584.434899:blk_co_pr"..., 112) = 112
    [pid  9005] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
    Process 24964 attached
    [pid  8988] write(85, "worker", 6)      = 6
    [pid 24964] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
    [pid  9005] write(2, "8988@1498054584.441258:blk_co_pr"..., 112) = 112
    [pid 24964] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
    [pid  9005] write(2, "8988@1498054585.063087:blk_co_pw"..., 114) = 114

    $ tail strace.out
    [pid  9005] write(2, "8988@1498054600.032253:paio_subm"..., 100) = 100
    [pid 24964] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
    [pid  9005] write(2, "8988@1498054600.141628:blk_co_pw"..., 112) = 112
    [pid 24964] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
    [pid  9005] write(2, "8988@1498054600.144293:paio_subm"..., 100) = 100
    [pid 24964] write(8, "\1\0\0\0\0\0\0\0", 8) = 8

    $ awk '{print $3}' strace.out | sort | uniq -c
          1 +++
          2 attached
          4 detached
       1053 write(2,
       1056 write(8,
          1 write(85,

I'm not sure where these fds lead to:-

    $ sudo ls -l /proc/8988/fd/2
    l-wx------ 1 qemu qemu 64 Jun 21 19:41 /proc/8988/fd/2 -> pipe:[705181]

    $ sudo ls -l /proc/8988/fd/8
    lrwx------ 1 qemu qemu 64 Jun 21 19:41 /proc/8988/fd/8 ->
anon_inode:[eventfd]

Still no ftrace events that I enabled:
    $ sudo ./ftrace-kvm.sh dd-ftrace.out sleep 20
    Using dd-ftrace.out as trace name. Continue?
    Copying trace to dd-ftrace.out

    $ wc -l dd-ftrace.out
    272676 dd-ftrace.out


    $ cut -b53- dd-ftrace.out | awk '{print $1}' | sort | uniq -c
          7
          1 h
          1 irq
       1185 kvm_ack_irq:
       5968 kvm_apic:
       5608 kvm_apic_accept_irq:
      15526 kvm_emulate_insn:
      60895 kvm_entry:
       5608 kvm_eoi:
      60912 kvm_exit:
       3862 kvm_fpu:
       5608 kvm_inj_virq:
       5925 kvm_ioapic_set_irq:
       8436 kvm_msr:
        204 kvm_page_fault:
       5925 kvm_pic_set_irq:
      36024 kvm_pio:
       4412 kvm_pv_eoi:
       5925 kvm_set_irq:
      36024 kvm_userspace_exit:
       4618 kvm_vcpu_wakeup:
          1 #P:24
          1 TION
    ======= ========
     272676

I tried strace on libvirtd and restarted the VM, but I'm not sure
what's going on:

    [pid 25167] fstat(2, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
    [pid 25167] mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5cdff0a000
    [pid 25167] write(2, "2017-06-21T14:23:18.470901Z qemu"..., 134) = 134
    .
    .
    .
    [pid 25167] write(2, "25167@1498054998.482112:bdrv_ope"..., 140) = 140
    .
    .
    .
    [pid 25167] write(2, "25167@1498054998.483315:bdrv_ope"..., 141) = 141


qemu cmd line

    $ strings -1 /proc/25167/cmdline
    /home/prasun/qemu-install/bin/qemu-system-x86_64
    -name
    guest=generic-qemu-system-x86_64,debug-threads=on
    -S
    -object
    secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-14-generic-qemu-system-/master-key.aes
    -machine
    pc-i440fx-2.9,accel=kvm,usb=off,vmport=off
    -cpu
    Opteron_G3
    -m
    1024
    -realtime
    mlock=off
    -smp
    1,sockets=1,cores=1,threads=1
    -uuid
    92c4ed02-0071-4876-9ed9-f18dd4435c1b
    -nographic
    -no-user-config
    -nodefaults
    -chardev
    socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-14-generic-qemu-system-/monitor.sock,server,nowait
    -mon
    chardev=charmonitor,id=monitor,mode=control
    -rtc
    base=utc,driftfix=slew
    -global
    kvm-pit.lost_tick_policy=discard
    -no-hpet
    -no-shutdown
    -global
    PIIX4_PM.disable_s3=1
    -global
    PIIX4_PM.disable_s4=1
    -boot
    strict=on
    -device
    ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x6.0x7
    -device
    ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x6
    -device
    ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x6.0x1
    -device
    ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x6.0x2
    -device
    virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5
    -drive
    file=/var/lib/libvirt/images/generic.qcow2,format=qcow2,if=none,id=drive-ide0-0-0
    -device
    ide-hd,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0,bootindex=1
    -drive
    if=none,id=drive-ide0-0-1,readonly=on
    -device
    ide-cd,bus=ide.0,unit=1,drive=drive-ide0-0-1,id=ide0-0-1
    -netdev
    tap,fd=26,id=hostnet0
    -device
    rtl8139,netdev=hostnet0,id=net0,mac=52:54:00:3d:db:fc,bus=pci.0,addr=0x3
    -chardev
    pty,id=charserial0
    -device
    isa-serial,chardev=charserial0,id=serial0
    -device
    intel-hda,id=sound0,bus=pci.0,addr=0x4
    -device
    hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0
    -device
    virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7
    -trace
    events=/home/prasun/my-trace-events
    -msg
    timestamp=on

Thanks
Prasun

Re: qemu/ftrace question

[Prasun Ratn]

>
> I see writes to fd 2 and 8:-
>

Oops, I was using the log backend - 2 is stderr of course.

With the ftrace backend build, I see this. It looks like qemu must be
run as root

        [pid 15759] open("/sys/kernel/debug/tracing/tracing_on",
O_WRONLY) = -1 EACCES (Permission denied)
        [pid 15759] open("/dev/null", O_WRONLY) = 10

        [pid 15759] stat("/var/lib/libvirt/images/generic.qcow2",
{st_mode=S_IFREG|0644, st_size=21478375424, ...}) = 0
        [pid 15759] write(10, "bdrv_open_common bs 0x7f77a19cfa"..., 116) = 116
        [pid 15759] open("/dev/urandom", O_RDONLY) = 15
        [pid 15759] read(15, "=S\202\372\17\17
\317\n\201G{\353\300\310\307", 16) = 16
        [pid 15759] close(15)                   = 0
        [pid 15759] futex(0x7f779f31d4a8, FUTEX_WAKE, 2147483647) = 0
        [pid 15759] open("/var/lib/libvirt/images/generic.qcow2",
O_RDWR|O_CLOEXEC) = 15
        [pid 15759] fstat(15, {st_mode=S_IFREG|0644,
st_size=21478375424, ...}) = 0
        [pid 15759] lseek(15, 0, SEEK_END)      = 21478375424
        [pid 15759] fstat(15, {st_mode=S_IFREG|0644,
st_size=21478375424, ...}) = 0
        [pid 15759] write(10, "bdrv_open_common bs 0x7f77a19c94"..., 117) = 117

With simple trace backend
        [pid 27775] open("trace-27775", O_WRONLY|O_CREAT|O_TRUNC,
0666) = -1 EACCES (Permission denied)

I assume, these methods work best when launching qemu directly, as
compared to using libvirt.

-Prasun

Re: qemu/ftrace question

[Stefan Hajnoczi]

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

On Thu, Jun 22, 2017 at 05:58:52AM +0530, Prasun Ratn wrote:
> >
> > I see writes to fd 2 and 8:-
> >
> 
> Oops, I was using the log backend - 2 is stderr of course.
> 
> With the ftrace backend build, I see this. It looks like qemu must be
> run as root
> 
>         [pid 15759] open("/sys/kernel/debug/tracing/tracing_on",
> O_WRONLY) = -1 EACCES (Permission denied)
>         [pid 15759] open("/dev/null", O_WRONLY) = 10
> 
>         [pid 15759] stat("/var/lib/libvirt/images/generic.qcow2",
> {st_mode=S_IFREG|0644, st_size=21478375424, ...}) = 0
>         [pid 15759] write(10, "bdrv_open_common bs 0x7f77a19cfa"..., 116) = 116
>         [pid 15759] open("/dev/urandom", O_RDONLY) = 15
>         [pid 15759] read(15, "=S\202\372\17\17
> \317\n\201G{\353\300\310\307", 16) = 16
>         [pid 15759] close(15)                   = 0
>         [pid 15759] futex(0x7f779f31d4a8, FUTEX_WAKE, 2147483647) = 0
>         [pid 15759] open("/var/lib/libvirt/images/generic.qcow2",
> O_RDWR|O_CLOEXEC) = 15
>         [pid 15759] fstat(15, {st_mode=S_IFREG|0644,
> st_size=21478375424, ...}) = 0
>         [pid 15759] lseek(15, 0, SEEK_END)      = 21478375424
>         [pid 15759] fstat(15, {st_mode=S_IFREG|0644,
> st_size=21478375424, ...}) = 0
>         [pid 15759] write(10, "bdrv_open_common bs 0x7f77a19c94"..., 117) = 117
> 
> With simple trace backend
>         [pid 27775] open("trace-27775", O_WRONLY|O_CREAT|O_TRUNC,
> 0666) = -1 EACCES (Permission denied)
> 
> I assume, these methods work best when launching qemu directly, as
> compared to using libvirt.

Yes, it's easier if you invoke QEMU yourself.  Usually libvirt is
configured to run QEMU in an environment with reduced privileges
(separate uid/gid, SELinux, etc).  That said, I'm pretty sure you can
change the libvirt configuration so that QEMU is launched as root :).

Stefan

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