* qemu/ftrace question
@ 2017-06-20 16:42 Prasun Ratn
2017-06-21 11:19 ` Stefan Hajnoczi
0 siblings, 1 reply; 5+ messages in thread
From: Prasun Ratn @ 2017-06-20 16:42 UTC (permalink / raw)
To: kvm
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
^ permalink raw reply [flat|nested] 5+ messages in thread* Re: qemu/ftrace question 2017-06-20 16:42 qemu/ftrace question Prasun Ratn @ 2017-06-21 11:19 ` Stefan Hajnoczi 2017-06-21 15:07 ` Prasun Ratn 0 siblings, 1 reply; 5+ messages in thread From: Stefan Hajnoczi @ 2017-06-21 11:19 UTC (permalink / raw) To: Prasun Ratn; +Cc: kvm [-- 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 --] ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: qemu/ftrace question 2017-06-21 11:19 ` Stefan Hajnoczi @ 2017-06-21 15:07 ` Prasun Ratn 2017-06-22 0:28 ` Prasun Ratn 0 siblings, 1 reply; 5+ messages in thread From: Prasun Ratn @ 2017-06-21 15:07 UTC (permalink / raw) To: Stefan Hajnoczi; +Cc: kvm > > 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 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: qemu/ftrace question 2017-06-21 15:07 ` Prasun Ratn @ 2017-06-22 0:28 ` Prasun Ratn 2017-06-23 12:48 ` Stefan Hajnoczi 0 siblings, 1 reply; 5+ messages in thread From: Prasun Ratn @ 2017-06-22 0:28 UTC (permalink / raw) To: Stefan Hajnoczi; +Cc: kvm > > 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 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: qemu/ftrace question 2017-06-22 0:28 ` Prasun Ratn @ 2017-06-23 12:48 ` Stefan Hajnoczi 0 siblings, 0 replies; 5+ messages in thread From: Stefan Hajnoczi @ 2017-06-23 12:48 UTC (permalink / raw) To: Prasun Ratn; +Cc: kvm [-- 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 --] ^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2017-06-23 12:49 UTC | newest] Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2017-06-20 16:42 qemu/ftrace question Prasun Ratn 2017-06-21 11:19 ` Stefan Hajnoczi 2017-06-21 15:07 ` Prasun Ratn 2017-06-22 0:28 ` Prasun Ratn 2017-06-23 12:48 ` Stefan Hajnoczi
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.