Bug 6156 - [crosstap] no trace message output on qemuarm
Summary: [crosstap] no trace message output on qemuarm
Status: VERIFIED NOTABUG
Alias: None
Product: OE-Core
Classification: Build System, Metadata & Runtime
Component: kernel (show other bugs)
Version: 1.6
Hardware: x86 Multiple
: Medium normal
Target Milestone: 2.2
Assignee: Tom Zanussi
QA Contact:
URL:
Whiteboard:
Depends on:
Blocks:
 
Reported: 2014-04-14 09:32 UTC by Yi Zhao
Modified: 2016-07-28 03:01 UTC (History)
9 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: Regression (Used to work)
Verified:
Documentation change: No (bug/feature does not impact docs)


Attachments
trace_open.stp (132 bytes, application/octet-stream)
2014-04-14 09:32 UTC, Yi Zhao
no flags Details
find the yocto kernel source tree (1.25 KB, patch)
2015-06-24 07:09 UTC, Kevin Hao
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Yi Zhao 2014-04-14 09:32:16 UTC
Created attachment 1912 [details]
trace_open.stp

Git rev: daisy/a0958261265049904fd78a2ba0198d46e5e65ea9

Steps:
1. Build qemuarm sato-sdk image and boot up
2. crosstap root@192.168.7.2 trace_open.stp

There is no trace message output in the host.
######################
$ crosstap root@192.168.7.2 ./trace_open.stp 
/buildarea3/yzhao1/poky-build/build-cross /buildarea3/yzhao1/poky-build/build-cross
/buildarea3/yzhao1/poky-build/build-cross
WARNING: Number of errors: 0, skipped probes: 31
######################

Check the message on target qemuarm:
####################
Apr 14 09:19:15 qemuarm auth.info sshd[607]: Accepted none for root from 192.168.7.1 port 57823 ssh2
Apr 14 09:19:19 qemuarm user.debug kernel: trace_open: systemtap: 2.5/0.155, base: bf07e000, memory: 17data/26text/4ctx/2058net/8alloc kb, probes: 2
Apr 14 09:20:00 qemuarm auth.info sshd[607]: Received disconnect from 192.168.7.1: 11: disconnected by user
####################


The trace_open.stp is attached. This script works well on qemuppc and qemux86-64
Comment 1 Tom Zanussi 2014-04-14 19:33:02 UTC
It sounds like you're just not generating any opens to trace.

You need to generate events so that something is actually traced e.g. on the target system cat /etc/* or something.
Comment 2 Yi Zhao 2014-04-15 02:30:47 UTC
(In reply to comment #1)
> It sounds like you're just not generating any opens to trace.
> 
> You need to generate events so that something is actually traced e.g. on the
> target system cat /etc/* or something.

I really did something like cat file, insmod and so on. but there is no any output.
Comment 3 Tom Zanussi 2014-04-19 01:35:34 UTC
replacing probe syscall.open with

probe kernel.function("sys_open")

works, but syscall.open should obviously work.  Will look into it.
Comment 4 Yi Zhao 2014-06-17 09:05:16 UTC
(In reply to comment #3)
> replacing probe syscall.open with
> 
> probe kernel.function("sys_open")
> 
> works, but syscall.open should obviously work.  Will look into it.

In 1.6.1, this issue still exists.

when replacing probe syscall.open with probe kernel,function("sys_open"), The output looks missing some message.

Here is the output with syscall.open in qemux86:
#############
sh(1487) open (461363d6, O_RDONLY|O_CLOEXEC)
sh(1487) open ("/lib/libtinfo.so.5", O_RDONLY|O_CLOEXEC)
sh(1487) open ("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC)
sh(1487) open ("/lib/libc.so.6", O_RDONLY|O_CLOEXEC)
sh(1487) open (080fba7f, O_RDWR|O_LARGEFILE|O_NONBLOCK)
sh(1487) open ("/proc/meminfo", O_RDONLY|O_CLOEXEC)
lsmod(1487) open (461363d6, O_RDONLY|O_CLOEXEC)
lsmod(1487) open ("/lib/libz.so.1", O_RDONLY|O_CLOEXEC)
lsmod(1487) open ("/lib/libc.so.6", O_RDONLY|O_CLOEXEC)
lsmod(1487) open ("/proc/cmdline", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/proc/modules", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/sys/module/hello/refcnt", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/sys/module/hello", O_RDONLY|O_LARGEFILE)
lsmod(1487) open ("/sys/module/trace_open/refcnt", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/sys/module/trace_open", O_RDONLY|O_LARGEFILE)
lsmod(1487) open ("/sys/module/nfsd/refcnt", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/sys/module/nfsd", O_RDONLY|O_LARGEFILE)
lsmod(1487) open ("/sys/module/uvesafb/refcnt", O_RDONLY|O_CLOEXEC|O_LARGEFILE)
lsmod(1487) open ("/sys/module/uvesafb", O_RDONLY|O_LARGEFILE)
sshd(1488) open ("/proc/sys/kernel/ngroups_max", O_RDONLY)
###########################

Here is the output with  kernel,function("sys_open") in qemux86:
#################
WARNING: never-assigned local variable 'argstr': identifier 'argstr' at sys_open.stp:3:59
 source: 	        printf ("%s(%d) open (%s)\n", execname(), pid(), argstr)
         	                                                         ^
ls(619) open ()
ls(619) open ()
ls(619) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
lsmod(620) open ()
insmod(621) open ()
insmod(621) open ()
insmod(621) open ()
insmod(621) open ()
insmod(621) open ()
#########################
Comment 5 Richard Purdie 2015-01-30 16:22:32 UTC
Yi: Does this bug still exist on 1.7 or 1.8 M2? Has this been retested recently?
Comment 6 Yi Zhao 2015-02-02 02:54:22 UTC
(In reply to comment #5)
> Yi: Does this bug still exist on 1.7 or 1.8 M2? Has this been retested
> recently?

Yes. It still exists both on 1.7 and 1.8 M2
Comment 7 Ke Zou 2015-02-06 03:12:32 UTC
This issue still exists in build 20150202-1
Comment 8 Yi Zhao 2015-04-01 10:00:49 UTC
This issue still exists in 1.8 M4 RC1
Comment 9 Ke Zou 2015-04-10 06:09:45 UTC
This issue still exists in 1.8 M4 RC2
Comment 10 Kevin Hao 2015-06-24 07:09:26 UTC
Created attachment 2560 [details]
find the yocto kernel source tree
Comment 11 Alexandru Georgescu 2016-02-04 09:57:26 UTC
(In reply to comment #10)
> Created attachment 2560 [details]
> find the yocto kernel source tree

seems that the issue still exists in YP 2.1_M2.rc1
master/3d2c0f5902cacf9d8544bf263b51ef0dd1a7218c
Comment 12 Tom Zanussi 2016-07-07 16:27:19 UTC
Currently in krogoth, we can't even get to the point where this bug can be tested because of stap module compilation errors because the 4.4 kernel removed these defines:

/usr/local/dev/yocto/krogoth-test/build/tmp/sysroots/x86_64-linux/usr/share/systemtap/runtime/linux/alloc.c:19:8: error: '__GFP_WAIT' undeclared (first use in this function)
/usr/local/dev/yocto/krogoth-test/build/tmp/sysroots/x86_64-linux/usr/share/systemtap/runtime/stp_utrace.c:785:50: error: 'GFP_IOFS' undeclared (first use in this function)

Once those are fixed, things work properly (tested on Ubuntu 16.04).  The key is that you need to generate some file open activity on the target in order for anything to show up.  (You also need to make sure you can ssh into the target on that address - if that doesn't work, neither will the script).

e.g.


trz@guayaba:~/yocto/krogoth-bugtest/build$ crosstap root@192.168.7.2 trace_open.stp
~/yocto/krogoth-bugtest/build ~/yocto/krogoth-bugtest/build
~/yocto/krogoth-bugtest/build
The authenticity of host '192.168.7.2 (192.168.7.2)' can't be established.
ECDSA key fingerprint is SHA256:YFrNOlOVwLCwaaeq/8PYwCgIlZSnxgwpux9ZEIPR4BU.
Are you sure you want to continue connecting (yes/no)? yes
syslogd(740) open ("/var/log/messages", O_WRONLY|O_CREAT|O_NOCTTY|O_APPEND|O_NONBLOCK|O_LARGEFILE, 0666)
matchbox-deskto(921) open ("/proc/self/fd", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC)
matchbox-deskto(921) open (b69eb7c4, O_RDONLY|O_LARGEFILE)
matchbox-termin(921) open ("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/usr/lib/libvte.so.9", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/usr/lib/libgtk-x11-2.0.so.0", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/usr/lib/libgobject-2.0.so.0", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/usr/lib/libglib-2.0.so.0", O_RDONLY|O_CLOEXEC)
matchbox-panel(802) open ("/usr/lib/gio/modules", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC)
matchbox-panel(802) open ("/usr/lib/gio/modules/giomodule.cache", O_RDONLY|O_LARGEFILE)
matchbox-termin(921) open ("/lib/tls/v5l/vfp/libc.so.6", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/lib/tls/v5l/libc.so.6", O_RDONLY|O_CLOEXEC)
matchbox-termin(921) open ("/lib/tls/vfp/libc.so.6", O_RDONLY|O_CLOEXEC)
.
.
.
matchbox-termin(921) open ("/usr/share/icons/default/cursors/00000000000000000000000000000000", O_RDONLY)
matchbox-termin(921) open ("/usr/share/icons/default/index.theme", O_RDONLY)
matchbox-termin(921) open ("/usr/share/pixmaps/default/cursors/00000000000000000000000000000000", O_RDONLY)
matchbox-termin(921) open ("/usr/share/pixmaps/default/index.theme", O_RDONLY)
matchbox-panel(802) open ("/usr/share/icons/Sato/48x48/mimetypes/application-x-executable.png", O_RDONLY|O_LARGEFILE)
matchbox-panel(802) open ("/usr/share/icons/Sato/48x48/apps/panel-user-desktop.png", O_RDONLY|O_LARGEFILE)
matchbox-termin(921) open ("/home/root/.Xdefaults", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults-qemuarm", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults-qemuarm", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults-qemuarm", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults-qemuarm", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults", O_RDONLY)
matchbox-termin(921) open ("/home/root/.Xdefaults-qemuarm", O_RDONLY)
WARNING: Number of errors: 0, skipped probes: 1
Comment 13 Tom Zanussi 2016-07-07 17:31:52 UTC
I poseted a patch to fix the krogoth module build error, which you can find here:

http://lists.openembedded.org/pipermail/openembedded-core/2016-July/123617.html
Comment 14 Tom Zanussi 2016-07-08 15:06:13 UTC
Things are also working fine in master, with systemtap 3.0, so I'm closing this as resolved, not a bug.  Tested on poky/master commit 4e889c04ba518dac492c193224a790a877f43f40.

For future testing, please first make sure you can successfully ssh as root into the target machine before running the test.  You also need to generate file open activity for it to show up in the output e.g. open the terminal or leafpad once the probe is registered.

It also takes awhile to compile the test script on the host - this is something that's expected due to the way systemtap works.  The problem with this is that you may have thought the probe was registered and gone and done your file open activity, but systemtap is still compiling and therefore missed the opens.  You may have to try again if you miss the opens, or just keep opening things until you see the output.
Comment 15 Yi Zhao 2016-07-28 03:01:07 UTC
Verified with 2.2 M2 RC1
Git rev: master/36feb38045b7a2af86ece147fec54b0db3bf491f