[Bug runtime/4904] New: Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[Bug runtime/4904] New: Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[bharata at linux dot vnet dot ibm dot com]

SystemTap translator/driver (version 0.5.15/Red Hat elfutils 0.125 built 2007-08-01)

I inserted a set of probes into fs/namespace.c:sys_pivot_root() using line
numbers and when the probes are hit, they aren't present in the expected order.
In the present case, I have 9 probes and I expect them to hit in the increasing
order (probe 1 followed by 2 etc till 9), but stap shows all probepoints mixed up.

Next /sys/kernel/debug/kprobes/list shows all the probepoints to be at the same
location which is not true. Additionally it shows 13 probepoints, while I had 9
in stap script.

The snippet of fs/namespace.c:sys_pivot_root() (from 2.6.22-rc6-mm1) where I
have inserted the probes looks like this:

   1814 asmlinkage long sys_pivot_root(const char __user * new_root,
   1815                                const char __user * put_old)
   1816 {
   1817         struct vfsmount *tmp;
   1818         struct nameidata new_nd, old_nd, parent_nd, root_parent, user_nd
       ;
   1819         int error;
   1820 
   1821         if (!capable(CAP_SYS_ADMIN))
   1822                 return -EPERM;
   1823 
   1824         lock_kernel();
   1825 
   1826         error = __user_walk(new_root, LOOKUP_FOLLOW | LOOKUP_DIRECTORY,
   1827                             &new_nd);
   1828         if (error)
   1829                 goto out0;
   1830         error = -EINVAL;
   1831         if (!check_mnt(new_nd.mnt))
   1832                 goto out1;
   1833 
   1834         error = __user_walk(put_old, LOOKUP_FOLLOW | LOOKUP_DIRECTORY, &
       old_nd);
   1835         if (error)
   1836                 goto out1;
   1837 
   1838         error = security_sb_pivotroot(&old_nd, &new_nd);
   1839         if (error) {
   1840                 path_release(&old_nd);
   1841                 goto out1;
   1842         }
   1843 
   1844         read_lock(&current->fs->lock);
   1845         user_nd.mnt = mntget(current->fs->rootmnt);
   1846         user_nd.dentry = dget(current->fs->root);
   1847         read_unlock(&current->fs->lock);
   1848         down_write(&namespace_sem);
   1849         mutex_lock(&old_nd.dentry->d_inode->i_mutex);
   1850         error = -EINVAL;
   1851         if (IS_MNT_SHARED(old_nd.mnt) ||
   1852                 IS_MNT_SHARED(new_nd.mnt->mnt_parent) ||
   1853                 IS_MNT_SHARED(user_nd.mnt->mnt_parent))
   1854                 goto out2;
   1855         if (!check_mnt(user_nd.mnt))
   1856                 goto out2;
   1857         error = -ENOENT;
   1858         if (IS_DEADDIR(new_nd.dentry->d_inode))
   1859                 goto out2;
   1860         if (d_unhashed(new_nd.dentry) && !IS_ROOT(new_nd.dentry))
   1861                 goto out2;
   1862         if (d_unhashed(old_nd.dentry) && !IS_ROOT(old_nd.dentry))
   1863                 goto out2;
   1864         error = -EBUSY;
   1865         if (new_nd.mnt == user_nd.mnt || old_nd.mnt == user_nd.mnt)
   1866                 goto out2; /* loop, on the same file system  */
   1867         error = -EINVAL;
   1868         if (user_nd.mnt->mnt_root != user_nd.dentry)
   1869                 goto out2; /* not a mountpoint */
   1870         if (user_nd.mnt->mnt_parent == user_nd.mnt)
   1871                 goto out2; /* not attached */
   1872         if (new_nd.mnt->mnt_root != new_nd.dentry)
   1873                 goto out2; /* not a mountpoint */
   1874         if (new_nd.mnt->mnt_parent == new_nd.mnt)
   1875                 goto out2; /* not attached */
   1876         tmp = old_nd.mnt; /* make sure we can reach put_old from new_roo
       t */

My stap script looks like this:

probe kernel.function("*@fs/namespace.c:1826") {
        printf("cpu %d, time:%d: probe1\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1834") {
        printf("cpu %d, time:%d: probe2\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1851") {
        printf("cpu %d, time:%d: probe3\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1858") {
        printf("cpu %d, time:%d: probe4\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1864") {
        printf("cpu %d, time:%d: probe5\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1868") {
        printf("cpu %d, time:%d: probe6\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1870") {
        printf("cpu %d, time:%d: probe7\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1872") {
        printf("cpu %d, time:%d: probe8\n", cpu(), gettimeofday_us());
}

probe kernel.function("*@fs/namespace.c:1874") {
        printf("cpu %d, time:%d: probe9\n", cpu(), gettimeofday_us());
}

stap output I get when I do a pivot_root looks like this: (This is where I
suspect wrong ordering of probepoints)

cpu 0, time:1186547494692726: probe9
cpu 0, time:1186547494692818: probe8
cpu 0, time:1186547494692821: probe7
cpu 0, time:1186547494692824: probe6
cpu 0, time:1186547494692827: probe6
cpu 0, time:1186547494692829: probe5
cpu 0, time:1186547494692832: probe4
cpu 0, time:1186547494692834: probe4
cpu 0, time:1186547494692837: probe3
cpu 0, time:1186547494692840: probe2
cpu 0, time:1186547494692842: probe2
cpu 0, time:1186547494692845: probe1
cpu 0, time:1186547494692847: probe1

/sys/kernel/debug/kprobes/list looks like this: (all entries are same)

c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1   
c0194b23  k  sys_pivot_root+0x1

Another unrelated problem is that in the above code snippet, I can't insert
probepoint at line no:1831 because check_mnt() is a inline function. This looks
like a drawback for stap user.

-- 
           Summary: Wrong ordering of probepoints in stap output + incorrect
                    lising probepoints by kprobes
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: bharata at linux dot vnet dot ibm dot com


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[bharata at linux dot vnet dot ibm dot com]

------- Additional Comments From bharata at linux dot vnet dot ibm dot com  2007-08-08 06:06 -------
Created an attachment (id=1953)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=1953&action=view)
stap -k output

The .c file obtained for the stap script by doing stap -k

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[joshua dot i dot stone at intel dot com]

------- Additional Comments From joshua dot i dot stone at intel dot com  2007-08-08 06:21 -------
I think that kernel.statement() probes are what you're looking for.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[srinivasa at in dot ibm dot com]

------- Additional Comments From srinivasa at in dot ibm dot com  2007-08-08 07:00 -------
Bharata 
 Looks like your stap script is putting probe on particular kernel
function(sys_pivot_root), rather than on different statements in that function.
Hence mismatch in ordering.
 Let me try it out with kernel.statement





-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[bharata at linux dot vnet dot ibm dot com]

------- Additional Comments From bharata at linux dot vnet dot ibm dot com  2007-08-08 08:35 -------
Ok, I replaced all kernel.function probes with kernel.statement probes, but
ended up in other problems. I now get errors like this:

semantic error: multiple addresses for fs/namespace.c:1826 (try
fs/namespace.c:1825 or fs/namespace.c:1827)
semantic error: no match for probe point while resolving probe point
kernel.statement("*@fs/namespace.c:1826")
semantic error: multiple addresses for fs/namespace.c:1834 (try
fs/namespace.c:1833 or fs/namespace.c:1836)
semantic error: no match for probe point while resolving probe point
kernel.statement("*@fs/namespace.c:1834")
semantic error: multiple addresses for fs/namespace.c:1858 (try
fs/namespace.c:1857 or fs/namespace.c:1859)
semantic error: no match for probe point while resolving probe point
kernel.statement("*@fs/namespace.c:1858")
semantic error: multiple addresses for fs/namespace.c:1868 (try
fs/namespace.c:1867 or fs/namespace.c:1869)
semantic error: no match for probe point while resolving probe point
kernel.statement("*@fs/namespace.c:1868")

If you look at the first error here stap is asking me to either
- put probe on 1825 which is a blank line which is blank line. This won't work
(see bug #4899)
or
- put probe on 1827 which is not a valid full C statement.

Am I just unfamiliar with stap usage or is this a bug ?



-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] Wrong ordering of probepoints in stap output + incorrect lising probepoints by kprobes

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2007-08-08 11:10 -------
> Ok, I replaced all kernel.function probes with kernel.statement probes, but
> ended up in other problems. I now get errors like this [...]

You are seeing effects of the smearing of statements due to compiler optimization.
Often, there isn't a single appropriate address to probe for a given statement
position.

We should do better in handling such cases though:
* suggested alternatives should be confirmed usable so that a user is not led astray
* consider applying more aggressive heuristics to map a user's request into a
probe "nearby", even if not strictly correct in some sense
* a probe syntax should be available to allow systemtap to search for all
probe-able lines in a range: perhaps something like
   foo.statement("*@file.c:200-300")


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|Wrong ordering of           |hard to use statement probes
                   |probepoints in stap output +|for line-by-line tracing
                   |incorrect lising probepoints|
                   |by kprobes                  |


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[srinivasa at in dot ibm dot com]

------- Additional Comments From srinivasa at in dot ibm dot com  2008-01-21 14:27 -------
Created an attachment (id=2207)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=2207&action=view)
patch to solve the problem.

Frank 
 If user probes the kernel with below style,
	 1) probe kernel.statement("*@kernel/sched.c:1151") {
	 2) probe kernel.function("*@kernel/sched.c:1151")  {

there is chance the probe being at appropriate place( line number different
than the user specified) and user is not informed about it. Thats one of the
causes for the above problem. 

So above patch informs the user about new line number, in which it has put the
probe.

Please let me know your comments

Thanks
 Srinivasa DS

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-01-21 14:42 -------
(In reply to comment #6)
> Created an attachment (id=2207)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=2207&action=view)

A warning message of this sort is fine, but please see other
warning messages for wording.formatting style.  It should also
observe session.suppress_warnings.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-01-21 14:45 -------
*** Bug 3534 has been marked as a duplicate of this bug. ***

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fche at redhat dot com


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[srinivasa at in dot ibm dot com]

------- Additional Comments From srinivasa at in dot ibm dot com  2008-01-22 10:11 -------
Frank 
 I was using this script, 
   probe kernel.statement("*@kernel/sched.c:100"), which points to a comment 
statement in sched.c, but systemtap was putting probe point to first function 
in that file at line number 122. This is good.  What is missing here, a warning 
which tells user that "Real probe point in source file(line number) is 
different".


=================================
[root@llm27lp1 src]# ./stap -p2 /root/b.stp
Line number 122 is probed instead of 100 in file 'kernel/sched.c'
# global embedded code
%{
#include <linux/time.h>
%}
# functions
cpu:long ()
gettimeofday_ns:long ()
gettimeofday_us:long ()
# probes
kernel.statement("sg_div_cpu_power@kernel/sched.c:100") /* pc=0x69090 */ /* <- 
kernel.statement("sg_div_cpu_power@kernel/sched.c:100") */
===========================

Thanks
 Srinivasa DS

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/4904] hard to use statement probes for line-by-line tracing

[scox at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
         AssignedTo|systemtap at sources dot    |scox at redhat dot com
                   |redhat dot com              |
             Status|NEW                         |ASSIGNED


http://sourceware.org/bugzilla/show_bug.cgi?id=4904

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.