Segmentation Fault: Task died at uprobe probepoint

Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

Hi All,

I have recently installed SystemTap on my Ubuntu 9.04 based system. I
have Linux kernel 2.6.29.1 with utrace support (I used the utrace
patch from http://people.redhat.com/roland/utrace/old/2.6.29/) . I
wrote a very simple program to test out the userspace probe
functionality. Here is the stap script I wrote:

probe process("/home/gdhiman/tests/uprobe-test").begin
{
        printf("uprobe-test begin!!\n")
}

probe process("/home/gdhiman/tests/uprobe-test").function("test_func")
{
        printf("test_func called!\n");
        log($$parms);
}

The uprobe-test code is as follows:

int test_func(int i)
{
        printf("%d\n", i);
        return j;
}

int main()
{
        int i;
        i = test_func(5);
        return 0;
}

Then I ran the script as root using stap -v test.stp; it is compiled
and inserted successfully. I see the following message if I do dmesg:
[ 1694.148460] stap_9736f2321b446f9fc03126194f89aac2_1643: systemtap:
1.2/0.131, base: ffffffffa0010000, memory:
136data/29text/10ctx/13net/34alloc kb, probes: 2

However, when i actually run uprobe-test, although both the probes
fire successfully, the task generates a segmentation fault and dies on
the 'test_func' probe. I see the following message on doing dmesg:
[ 1709.650827] Task died at uprobe probepoint:  pid/tgid = 3934/3934,
probepoint = 0x400517

I am not sure why is this happening. Is there something wrong in the
patch I used, or am I making some stupid mistake in programming the
probes? Any insights into what might be happening and how to resolve
the issue would be really helpful.

Thanks in advance,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Srikar Dronamraju]

Hi, 

> 
> probe process("/home/gdhiman/tests/uprobe-test").begin
> {
>         printf("uprobe-test begin!!\n")
> }
> 
> probe process("/home/gdhiman/tests/uprobe-test").function("test_func")
> {
>         printf("test_func called!\n");
>         log($$parms);
> }
> 
> The uprobe-test code is as follows:
> 
> int test_func(int i)
> {
>         printf("%d\n", i);
>         return j;
	        ^^^^^ 
	Guess you meant "return i;"

> }
> 
> int main()
> {
>         int i;
>         i = test_func(5);
>         return 0;
> }
> 
> 

> Then I ran the script as root using stap -v test.stp; it is compiled
> and inserted successfully. I see the following message if I do dmesg:
> [ 1694.148460] stap_9736f2321b446f9fc03126194f89aac2_1643: systemtap:
> 1.2/0.131, base: ffffffffa0010000, memory
> 136data/29text/10ctx/13net/34alloc kb, probes: 2

Looks to me that you are using a pretty recent systemtap with a pretty 
old elfutils. Is is possible to try building systemtap with a later
version of elfutils?

> However, when i actually run uprobe-test, although both the probes
> fire successfully, the task generates a segmentation fault and dies on
> the 'test_func' probe. I see the following message on doing dmesg:

> [ 1709.650827] Task died at uprobe probepoint:  pid/tgid = 3934/3934,
> probepoint = 0x400517


This means that the process died before the uprobe operation completed.
i.e either it was still running the handler or singlestep operation
hadnt occurred.  
- Did you try using the core with gdb? Does address in bt and
  disassemble output of test_func show the same address?

I am not able to see this problem. (I am running on a different kernel)

--
Regards
Srikar

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Mon, Jun 14, 2010 at 12:00 AM, Srikar Dronamraju
<srikar@linux.vnet.ibm.com> wrote:

>> The uprobe-test code is as follows:
>>
>> int test_func(int i)
>> {
>>         printf("%d\n", i);
>>         return j;
>                ^^^^^
>        Guess you meant "return i;"

Yes, I meant 'i' :)

>> Then I ran the script as root using stap -v test.stp; it is compiled
>> and inserted successfully. I see the following message if I do dmesg:
>> [ 1694.148460] stap_9736f2321b446f9fc03126194f89aac2_1643: systemtap:
>> 1.2/0.131, base: ffffffffa0010000, memory
>> 136data/29text/10ctx/13net/34alloc kb, probes: 2
>
> Looks to me that you are using a pretty recent systemtap with a pretty
> old elfutils. Is is possible to try building systemtap with a later
> version of elfutils?
>

I have version 0.13a installed on my system. Is that too old? I can
give it a shot with latter versions.

>> However, when i actually run uprobe-test, although both the probes
>> fire successfully, the task generates a segmentation fault and dies on
>> the 'test_func' probe. I see the following message on doing dmesg:
>
>> [ 1709.650827] Task died at uprobe probepoint:  pid/tgid = 3934/3934,
>> probepoint = 0x400517
>
>
> This means that the process died before the uprobe operation completed.
> i.e either it was still running the handler or singlestep operation
> hadnt occurred.
> - Did you try using the core with gdb? Does address in bt and
>  disassemble output of test_func show the same address?

Actually the uprobe is firing. I see the output of the following
probe, when the function gets called:
 probe process("/home/gdhiman/tests/uprobe-test").function("test_func")
 {
        printf("test_func called!\n");
        log($$parms);
 }

However, the program immediately dies. The address of the function is
0x400517, the same as that shown in the probepoint.

>
> I am not able to see this problem. (I am running on a different kernel)
>

Which versions (systemtap and kernel) are you using? I might give them
a shot as well.

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Mark Wielaard]

On Mon, 2010-06-14 at 17:43 -0700, Gaurav Dhiman wrote:
> > Looks to me that you are using a pretty recent systemtap with a pretty
> > old elfutils. Is is possible to try building systemtap with a later
> > version of elfutils?
> >
> I have version 0.13a installed on my system. Is that too old? I can
> give it a shot with latter versions.

That is pretty old. Some versions before 0.142 had bugs that could
result in us misplacing probes. But that isn't the issue you are seeing
here, since even if the probe was misplaced it should still not crash
the binary you are inspecting.

If possible, please do try using elfutils-0.142+ (latest is 0.147). Even
though that shouldn't matter in your case.

> > I am not able to see this problem. (I am running on a different kernel)
> >
> 
> Which versions (systemtap and kernel) are you using? I might give them
> a shot as well.

I was also unable to replicate. Using systemtap 1.2 or current git tip.
elfutils 0.147. kernel 2.6.32-33.el6.x86_64 or 2.6.33.5-112.fc13.i686

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Tue, Jun 15, 2010 at 2:11 AM, Mark Wielaard <mjw@redhat.com> wrote:
> On Mon, 2010-06-14 at 17:43 -0700, Gaurav Dhiman wrote:
>> > Looks to me that you are using a pretty recent systemtap with a pretty
>> > old elfutils. Is is possible to try building systemtap with a later
>> > version of elfutils?
>> >
>> I have version 0.13a installed on my system. Is that too old? I can
>> give it a shot with latter versions.
>
> That is pretty old. Some versions before 0.142 had bugs that could
> result in us misplacing probes. But that isn't the issue you are seeing
> here, since even if the probe was misplaced it should still not crash
> the binary you are inspecting.
>
> If possible, please do try using elfutils-0.142+ (latest is 0.147). Even
> though that shouldn't matter in your case.

I have now upgraded to elfutils 0.143, and now the SIGSEGV is not
happening anymore. But now it gives a Trace/breakpoint trap instead
and the probe is removed just like it was happening before. The binary
now likes like this:

0000000000400550 <test_func>:
  400550:       53                      push   %rbx
  400551:       89 fa                   mov    %edi,%edx
  400553:       89 fb                   mov    %edi,%ebx
  400555:       be 7c 06 40 00          mov    $0x40067c,%esi
  40055a:       bf 01 00 00 00          mov    $0x1,%edi
  40055f:       31 c0                   xor    %eax,%eax
  400561:       e8 da fe ff ff          callq  400440 <__printf_chk@plt>
  400566:       89 d8                   mov    %ebx,%eax
  400568:       5b                      pop    %rbx
  400569:       c3                      retq
  40056a:       66 0f 1f 44 00 00       nopw   0x0(%rax,%rax,1)

And the systemtap debug messages that I see now are:

stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process
uprobe-test[13414] addr 0000000000400550 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:3")
stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process
uprobe-test[13414] reloc 0000000000400550 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:3")


>> > I am not able to see this problem. (I am running on a different kernel)
>> >
>>
>> Which versions (systemtap and kernel) are you using? I might give them
>> a shot as well.
>
> I was also unable to replicate. Using systemtap 1.2 or current git tip.
> elfutils 0.147. kernel 2.6.32-33.el6.x86_64 or 2.6.33.5-112.fc13.i686
>

I am using kernel 2.6.29, which has the corresponding utrace patch.
Can it be the reason that the older version is not compatible with the
latest version of systemtap? Another thing that I forgot to mention in
my previous emails is that I am running this kernel and systemtap
inside a Xen DomU. Does that make a difference?

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Frank Ch. Eigler]

Gaurav Dhiman <dimanuec@gmail.com> writes:

> [...]
> I am using kernel 2.6.29, which has the corresponding utrace patch.
> Can it be the reason that the older version is not compatible with the
> latest version of systemtap?

It should work.  I'm surprised that an elfutils version change
produced anything visibly different.  Perhaps you could try a fresh
copy of 0.147 (and build systemtap with --with-elfutils=PATH)?

> Another thing that I forgot to mention in my previous emails is that
> I am running this kernel and systemtap inside a Xen DomU. Does that
> make a difference?

We have had some problems in the long-ago past with xen not emulating
breakpoints inside the guests quite right.  Would you be in a position
to try kvm and/or hardware?


- FChE

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Wed, Jun 16, 2010 at 6:53 AM, Frank Ch. Eigler <fche@redhat.com> wrote:
> Gaurav Dhiman <dimanuec@gmail.com> writes:
>
>> [...]
>> I am using kernel 2.6.29, which has the corresponding utrace patch.
>> Can it be the reason that the older version is not compatible with the
>> latest version of systemtap?
>
> It should work.  I'm surprised that an elfutils version change
> produced anything visibly different.  Perhaps you could try a fresh
> copy of 0.147 (and build systemtap with --with-elfutils=PATH)?
>
>> Another thing that I forgot to mention in my previous emails is that
>> I am running this kernel and systemtap inside a Xen DomU. Does that
>> make a difference?
>
> We have had some problems in the long-ago past with xen not emulating
> breakpoints inside the guests quite right.  Would you be in a position
> to try kvm and/or hardware?
>

Well, so I gave the whole thing a shot with KVM on the same machine.
This time I ran with Linux kernel 2.6.34 (with utrace patch applied).
I used systemtap with elfutils 0.147. And it worked (btw the 0.147
version did not work on the Xen DomU kernel)!!

So I believe it might be either a Xen related issue or might have
something to do with the fact that I am using Linux 2.6.34 now. I
might verify the latter by running 2.6.29 inside KVM. For reasons
specific to our setup, we cannot go beyond 2.6.29 for the Xen DomU.

I have also observed, that around 3 hunks of the utrace patch always
fail in tracehook.h. I typically apply them manually in the functions
they are supposed to go into. Is the patch not actively updated, or
these changes are outdated? I have appended my tracehook.h.rej below.

*************** static inline __must_check int tracehook
*** 134,139 ****
  */
 static inline void tracehook_report_syscall_exit(struct pt_regs
*regs, int step)
 {
       if (step && (task_ptrace(current) & PT_PTRACED)) {
               siginfo_t info;
               user_single_step_siginfo(current, regs, &info);
--- 140,148 ----
  */
 static inline void tracehook_report_syscall_exit(struct pt_regs
*regs, int step)
 {
+       if (task_utrace_flags(current) & UTRACE_EVENT(SYSCALL_EXIT))
+               utrace_report_syscall_exit(regs);
+
       if (step && (task_ptrace(current) & PT_PTRACED)) {
               siginfo_t info;
               user_single_step_siginfo(current, regs, &info);
*************** static inline void tracehook_signal_hand
*** 386,391 ****
                                           const struct k_sigaction *ka,
                                           struct pt_regs *regs, int stepping)
 {
       if (stepping && (task_ptrace(current) & PT_PTRACED))
               ptrace_notify(SIGTRAP);
 }
--- 434,441 ----
                                           const struct k_sigaction *ka,
                                           struct pt_regs *regs, int stepping)
 {
+       if (task_utrace_flags(current))
+               utrace_signal_handler(current, stepping);
       if (stepping && (task_ptrace(current) & PT_PTRACED))
               ptrace_notify(SIGTRAP);
 }
*************** static inline int tracehook_get_signal(s
*** 492,497 ****
  */
 static inline int tracehook_notify_jctl(int notify, int why)
 {
       return notify ?: task_ptrace(current) ? why : 0;
 }

--- 551,558 ----
  */
 static inline int tracehook_notify_jctl(int notify, int why)
 {
+       if (task_utrace_flags(current) & UTRACE_EVENT(JCTL))
+               utrace_report_jctl(notify, why);
       return notify ?: task_ptrace(current) ? why : 0;
 }

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Roland McGrath]

> I have also observed, that around 3 hunks of the utrace patch always
> fail in tracehook.h. I typically apply them manually in the functions
> they are supposed to go into. Is the patch not actively updated, or
> these changes are outdated? I have appended my tracehook.h.rej below.

What baseline kernel and what utrace patch are you using?

At http://people.redhat.com/~roland/utrace/
and git://git.kernel.org/pub/scm/linux/kernel/git/frob/linux-2.6-utrace.git
there are current patch-series/branches for 2.6-current (v2.6.35-rc3),
2.6.34 (e.g. rawhide), 2.6.33 (e.g. F-13), and 2.6.32 (e.g. F-12).

I just did the merge to update the 2.6-current to 2.6.35-rc3 from somewhere
in the post-2.6.34/pre-rc1 period, but it was automatic with no conflicts.


Thanks,
Roland

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Mon, Jun 21, 2010 at 6:43 PM, Roland McGrath <roland@redhat.com> wrote:
>> I have also observed, that around 3 hunks of the utrace patch always
>> fail in tracehook.h. I typically apply them manually in the functions
>> they are supposed to go into. Is the patch not actively updated, or
>> these changes are outdated? I have appended my tracehook.h.rej below.
>
> What baseline kernel and what utrace patch are you using?
>
> At http://people.redhat.com/~roland/utrace/
> and git://git.kernel.org/pub/scm/linux/kernel/git/frob/linux-2.6-utrace.git
> there are current patch-series/branches for 2.6-current (v2.6.35-rc3),
> 2.6.34 (e.g. rawhide), 2.6.33 (e.g. F-13), and 2.6.32 (e.g. F-12).
>
> I just did the merge to update the 2.6-current to 2.6.35-rc3 from somewhere
> in the post-2.6.34/pre-rc1 period, but it was automatic with no conflicts.
>

I got the 2.6.34 kernel from kernel.org, and the following utrace patch:
http://people.redhat.com/roland/utrace/2.6.34/utrace.patch

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Roland McGrath]

> I got the 2.6.34 kernel from kernel.org, and the following utrace patch:
> http://people.redhat.com/roland/utrace/2.6.34/utrace.patch

Follow the series file in that directory to apply the patches in proper order.


Thanks,
Roland

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Mon, Jun 21, 2010 at 9:07 PM, Roland McGrath <roland@redhat.com> wrote:
>> I got the 2.6.34 kernel from kernel.org, and the following utrace patch:
>> http://people.redhat.com/roland/utrace/2.6.34/utrace.patch
>
> Follow the series file in that directory to apply the patches in proper order.
>

My bad, I did not get those failed hunk messages when I followed the
order in the series file!

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Srikar Dronamraju]

> 
> Which versions (systemtap and kernel) are you using? I might give them
> a shot as well.

I run 2.6.32 kernels with latest snapshot of systemtap and elfutils.

Can you try removing the log($$parms) statement and see if it still
fails? I dont see a reason why it should make a difference but its just
a wild wild guess.

--
Thanks and Regards
Srikar

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Tue, Jun 15, 2010 at 3:37 AM, Srikar Dronamraju
<srikar@linux.vnet.ibm.com> wrote:
>>
>> Which versions (systemtap and kernel) are you using? I might give them
>> a shot as well.
>
> I run 2.6.32 kernels with latest snapshot of systemtap and elfutils.
>
> Can you try removing the log($$parms) statement and see if it still
> fails? I dont see a reason why it should make a difference but its just
> a wild wild guess.

No, it did not make any difference!

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Frank Ch. Eigler]

Gaurav Dhiman <dimanuec@gmail.com> writes:

> [...]
> I have recently installed SystemTap on my Ubuntu 9.04 based system. I
> have Linux kernel 2.6.29.1 with utrace support [...]

Great.

> [...]
> However, when i actually run uprobe-test, although both the probes
> fire successfully, the task generates a segmentation fault and dies on
> the 'test_func' probe. I see the following message on doing dmesg:
> [ 1709.650827] Task died at uprobe probepoint:  pid/tgid = 3934/3934,
> probepoint = 0x400517

Almost certainly it's a uprobes or utrace or systemtap bug, rather
than something you might have done wrong.  Can you collect more
information, such as systemtap git version, stap -vvvt -DDEBUG_UPROBES
traces, disassembly of your probe-target executable?

- FChE

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Mon, Jun 14, 2010 at 9:56 AM, Frank Ch. Eigler <fche@redhat.com> wrote:
> Gaurav Dhiman <dimanuec@gmail.com> writes:
>
>> [...]
>> I have recently installed SystemTap on my Ubuntu 9.04 based system. I
>> have Linux kernel 2.6.29.1 with utrace support [...]
>
> Great.
>
>> [...]
>> However, when i actually run uprobe-test, although both the probes
>> fire successfully, the task generates a segmentation fault and dies on
>> the 'test_func' probe. I see the following message on doing dmesg:
>> [ 1709.650827] Task died at uprobe probepoint:  pid/tgid = 3934/3934,
>> probepoint = 0x400517
>
> Almost certainly it's a uprobes or utrace or systemtap bug, rather
> than something you might have done wrong.  Can you collect more
> information, such as systemtap git version, stap -vvvt -DDEBUG_UPROBES
> traces, disassembly of your probe-target executable?

The following commit is on the head of the git log I have (I don't
know how to get the exact systemtap version):

commit b275171e26c0cf9441858209ac62e70b8ddda71d
Author: Josh Stone <jistone@redhat.com>
Date:   Thu Jun 10 16:05:29 2010 -0700

    PR11690: Remove a dtrace debug-print, and fix probe_perf

    Stan's commit 278c975 fixes the core issue; I'm just polishing...

    * dtrace.in: Comment out the debug-print before calling gcc.
    * scripts/probe_perf/bench.sh: Pass -DSTAP_SDT_V2 to dtrace.

Following are the logs from the Pass 5 of the run with stap -vvvt
-DDEBUG_UPROBES:

Pass 5: starting run.
Running /usr/local/bin/staprun -v -v -u
/tmp/stapmfXZax/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686.ko
staprun:main:273
modpath="/tmp/stapmfXZax/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686.ko",
modname="stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686"
staprun:init_staprun:211 init_staprun
spawning: /bin/grep -q unregister_uprobe /proc/kallsyms
staprun:insert_module:60 inserting module
staprun:insert_module:79 module options: _stp_bufsize=0
staprun:init_ctl_channel:31 Opened
/sys/kernel/debug/systemtap/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686/.cmd
(3)
staprun:close_ctl_channel:50 Closed ctl fd 3
execing: /usr/local/libexec/systemtap/stapio -v -v -u
/tmp/stapmfXZax/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686.ko
stapio:main:37 modpath="/tmp/stapmfXZax/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686.ko",
modname="stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686"
stapio:init_stapio:317 init_stapio
stapio:init_ctl_channel:31 Opened
/sys/kernel/debug/systemtap/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686/.cmd
(3)
stapio:stp_main_loop:494 in main loop
stapio:init_relayfs:238 initializing relayfs
stapio:init_relayfs:262 attempting to open
/sys/kernel/debug/systemtap/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686/trace0
stapio:init_relayfs:262 attempting to open
/sys/kernel/debug/systemtap/stap_0ebd34b5ef2ddf9f38803a661fa38a13_1686/trace1
stapio:init_relayfs:268 ncpus=1, bulkmode = 0
stapio:init_relayfs:345 starting threads
stapio:stp_main_loop:571 probe_start() returned 0
stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process
uprobe-test[25763] addr 0000000000400517 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
test begin!!
test_func called!
i=0x5
stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process
uprobe-test[25763] reloc 0000000000400517 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")

The program receives a SIGSEGV signal at this point.

By the probe target executable do you mean, the .ko file that is
generated? The disassembled file of that is pretty big, close to 17000
lines. Do you want that or something else?

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Frank Ch. Eigler]

Gaurav Dhiman <dimanuec@gmail.com> writes:

> [...]
> The following commit is on the head of the git log I have (I don't
> know how to get the exact systemtap version):
>
> commit b275171e26c0cf9441858209ac62e70b8ddda71d
> [...]

That's perfectly specific, thanks.

> [...]
> Following are the logs from the Pass 5 of the run with stap -vvvt
> -DDEBUG_UPROBES:
>
> Pass 5: starting run.
> [...]
> stapio:stp_main_loop:571 probe_start() returned 0
> stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process uprobe-test[25763] addr 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
> test begin!!
> test_func called!
> i=0x5
> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process uprobe-test[25763] reloc 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>
> The program receives a SIGSEGV signal at this point.

OK, something is wrong here.  See that -uprobe line?  It means stap
has for some reason determined that it's time to remove the uprobe,
but that should not happen until either the script or the target
program exits.

This will make things more verbose, but could you try adding
-DDEBUG_TASK_FINDER and -DDEBUG_TASK_FINDER_VMA to the stap
command line? 


> By the probe target executable do you mean, the .ko file that is
> generated? The disassembled file of that is pretty big, close to 17000
> lines. Do you want that or something else?

I meant the uprobe-test binary, just to see what instructions were
in the vicinity of the test_func function.  Just that area.


- FChE

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Mon, Jun 14, 2010 at 6:33 PM, Frank Ch. Eigler <fche@redhat.com> wrote:
> Gaurav Dhiman <dimanuec@gmail.com> writes:
>
>> [...]
>> The following commit is on the head of the git log I have (I don't
>> know how to get the exact systemtap version):
>>
>> commit b275171e26c0cf9441858209ac62e70b8ddda71d
>> [...]
>
> That's perfectly specific, thanks.
>
>> [...]
>> Following are the logs from the Pass 5 of the run with stap -vvvt
>> -DDEBUG_UPROBES:
>>
>> Pass 5: starting run.
>> [...]
>> stapio:stp_main_loop:571 probe_start() returned 0
>> stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process uprobe-test[25763] addr 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>> test begin!!
>> test_func called!
>> i=0x5
>> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process uprobe-test[25763] reloc 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>>
>> The program receives a SIGSEGV signal at this point.
>
> OK, something is wrong here.  See that -uprobe line?  It means stap
> has for some reason determined that it's time to remove the uprobe,
> but that should not happen until either the script or the target
> program exits.
>
> This will make things more verbose, but could you try adding
> -DDEBUG_TASK_FINDER and -DDEBUG_TASK_FINDER_VMA to the stap
> command line?
>

You are right, that looks suspicious; it is actually removing the
probe, when it should not be doing it. Here is the more verbose
output:

stap_uprobe_process_found:246: +proc pid 27237 stf ffffffffa001dce0
ffffffffa001dce0 path /home/gdhiman/tests/uprobe-test
stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process
uprobe-test[27237] addr 0000000000400517 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
test begin!!
_stp_tf_exec_cb:29: tsk 27237:27237 , register_p: 1, process_p: 1
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x400000
0x1000  0x0  r-xp  /home/gdhiman/tests/uprobe-test
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path
/home/gdhiman/tests/uprobe-test, addr 0x00400000, length 0x00001000,
offset 0x0, flags 0x8001875
_stp_tf_mmap_cb:63: vm_cb: matched path
/home/gdhiman/tests/uprobe-test to module (for sec: .absolute)
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x600000
0x2000  0x0  rw-p  /home/gdhiman/tests/uprobe-test
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path
/home/gdhiman/tests/uprobe-test, addr 0x00600000, length 0x00002000,
offset 0x0, flags 0x8101873
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x7faadb80e000
0x20000  0x0  r-xp  /lib/ld-2.9.so
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path /lib/ld-2.9.so, addr
0x7faadb80e000, length 0x00020000, offset 0x0, flags 0x8000875
_stp_tf_mmap_cb:92: registered 'ld-2.9.so' for 27237 (res:0)
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x7faadba2d000
0x2000  0x1f000  rw-p  /lib/ld-2.9.so
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path /lib/ld-2.9.so, addr
0x7faadba2d000, length 0x00002000, offset 0x1f000, flags 0x8100873
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadba2c000
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadba2a000
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadba25000
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x7faadba25000
0x5000  0x0  r--p  /etc/ld.so.cache
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path /etc/ld.so.cache,
addr 0x7faadba25000, length 0x00005000, offset 0x0, flags 0x8000071
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadb49c000
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x7faadb49c000
0x372000  0x0  r-xp  /lib/libc-2.9.so
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path /lib/libc-2.9.so,
addr 0x7faadb49c000, length 0x00372000, offset 0x0, flags 0x8000075
_stp_tf_mmap_cb:92: registered 'libc-2.9.so' for 27237 (res:0)
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadb804000
__stp_call_mmap_callbacks:599: pid 27237, a/l/o/p/path 0x7faadb804000
0x5000  0x168000  rw-p  /lib/libc-2.9.so
_stp_tf_mmap_cb:51: mmap_cb: tsk 27237:27237 path /lib/libc-2.9.so,
addr 0x7faadb804000, length 0x00005000, offset 0x168000, flags
0x8100073
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadb809000
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadba24000
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
mmap(0x0), returned 0x7faadba23000
__stp_utrace_task_finder_target_syscall_exit:1423: tsk 27237 found
munmap(0x7faadba25000), returned 0x0
test_func called!
i=0x5
stap_uprobe_process_found:246: -proc pid 27237 stf ffffffffa001dce0
ffffffffa001dce0 path /home/gdhiman/tests/uprobe-test
stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process
uprobe-test[27237] reloc 0000000000400517 pp
process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
_stp_tf_exec_cb:29: tsk 27237:27237 , register_p: 0, process_p: 1

>
> I meant the uprobe-test binary, just to see what instructions were
> in the vicinity of the test_func function.  Just that area.
>

Here it is:

000000000040050c <test_func>:
  40050c:       55                      push   %rbp
  40050d:       48 89 e5                mov    %rsp,%rbp
  400510:       48 83 ec 10             sub    $0x10,%rsp
  400514:       89 7d fc                mov    %edi,-0x4(%rbp)
  400517:       8b 75 fc                mov    -0x4(%rbp),%esi
  40051a:       bf 3c 06 40 00          mov    $0x40063c,%edi
  40051f:       b8 00 00 00 00          mov    $0x0,%eax
  400524:       e8 cf fe ff ff          callq  4003f8 <printf@plt>
  400529:       8b 45 fc                mov    -0x4(%rbp),%eax
  40052c:       c9                      leaveq
  40052d:       c3                      retq

000000000040052e <main>:
  40052e:       55                      push   %rbp
  40052f:       48 89 e5                mov    %rsp,%rbp
  400532:       48 83 ec 10             sub    $0x10,%rsp
  400536:       bf 05 00 00 00          mov    $0x5,%edi
  40053b:       e8 cc ff ff ff          callq  40050c <test_func>
  400540:       89 45 fc                mov    %eax,-0x4(%rbp)
  400543:       b8 00 00 00 00          mov    $0x0,%eax
  400548:       c9                      leaveq
  400549:       c3                      retq
  40054a:       90                      nop
  40054b:       90                      nop
  40054c:       90                      nop
  40054d:       90                      nop
  40054e:       90                      nop
  40054f:       90                      nop

Thanks,
-Gaurav

Re: Segmentation Fault: Task died at uprobe probepoint

[Mark Wielaard]

On Mon, 2010-06-14 at 20:52 -0700, Gaurav Dhiman wrote:
> On Mon, Jun 14, 2010 at 6:33 PM, Frank Ch. Eigler <fche@redhat.com> wrote:
> > Gaurav Dhiman <dimanuec@gmail.com> writes:
> >> [...]
> >> Following are the logs from the Pass 5 of the run with stap -vvvt
> >> -DDEBUG_UPROBES:
> >>
> >> Pass 5: starting run.
> >> [...]
> >> stapio:stp_main_loop:571 probe_start() returned 0
> >> stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process uprobe-test[25763] addr 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
> >> test begin!!
> >> test_func called!
> >> i=0x5
> >> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process uprobe-test[25763] reloc 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
> >>
> >> The program receives a SIGSEGV signal at this point.
> >
> > OK, something is wrong here.  See that -uprobe line?  It means stap
> > has for some reason determined that it's time to remove the uprobe,
> > but that should not happen until either the script or the target
> > program exits.
> >
> > This will make things more verbose, but could you try adding
> > -DDEBUG_TASK_FINDER and -DDEBUG_TASK_FINDER_VMA to the stap
> > command line?
> >
> You are right, that looks suspicious; it is actually removing the
> probe, when it should not be doing it. Here is the more verbose
> output:
> 
> test_func called!
> i=0x5
> stap_uprobe_process_found:246: -proc pid 27237 stf ffffffffa001dce0
> ffffffffa001dce0 path /home/gdhiman/tests/uprobe-test
> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process
> uprobe-test[27237] reloc 0000000000400517 pp
> process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
> _stp_tf_exec_cb:29: tsk 27237:27237 , register_p: 0, process_p: 1

Unless I am reading the logs wrong, I do think this is expected. The
process gets a SIGSEGV and so uprobes is notified that it needs to clean
up (-proc pid 27237 means process is gone).

> > I meant the uprobe-test binary, just to see what instructions were
> > in the vicinity of the test_func function.  Just that area.
> >
> 
> Here it is:
> 
> 000000000040050c <test_func>:
>   40050c:       55                      push   %rbp
>   40050d:       48 89 e5                mov    %rsp,%rbp
>   400510:       48 83 ec 10             sub    $0x10,%rsp
>   400514:       89 7d fc                mov    %edi,-0x4(%rbp)
>   400517:       8b 75 fc                mov    -0x4(%rbp),%esi
>   40051a:       bf 3c 06 40 00          mov    $0x40063c,%edi
>   40051f:       b8 00 00 00 00          mov    $0x0,%eax
>   400524:       e8 cf fe ff ff          callq  4003f8 <printf@plt>
>   400529:       8b 45 fc                mov    -0x4(%rbp),%eax
>   40052c:       c9                      leaveq
>   40052d:       c3                      retq

That does look OK, even though it looks different from my local build:

Dump of assembler code for function test_func:
   0x080483d0 <+0>:	push   %ebp
   0x080483d1 <+1>:	mov    %esp,%ebp
   0x080483d3 <+3>:	push   %ebx
   0x080483d4 <+4>:	sub    $0x14,%esp
   0x080483d7 <+7>:	mov    0x8(%ebp),%ebx
   0x080483da <+10>:	movl   $0x80484f4,(%esp)
   0x080483e1 <+17>:	mov    %ebx,0x4(%esp)
   0x080483e5 <+21>:	call   0x80482f4 <printf@plt>
   0x080483ea <+26>:	mov    %ebx,%eax
   0x080483ec <+28>:	add    $0x14,%esp
   0x080483ef <+31>:	pop    %ebx
   0x080483f0 <+32>:	pop    %ebp
   0x080483f1 <+33>:	ret    
End of assembler dump.

What compiler and flags did you use? Here gcc version 4.4.4 20100503
(Red Hat 4.4.4-2) with -g -O2.

If possible could you set ulimit -c unlimited and catch the core file of
the program and give the disassembly from test_func in the core? Maybe
the breakpoint instruction in there was misplaced?

Thanks,

Mark 

Re: Segmentation Fault: Task died at uprobe probepoint

[Gaurav Dhiman]

On Tue, Jun 15, 2010 at 2:23 AM, Mark Wielaard <mjw@redhat.com> wrote:
> On Mon, 2010-06-14 at 20:52 -0700, Gaurav Dhiman wrote:
>> On Mon, Jun 14, 2010 at 6:33 PM, Frank Ch. Eigler <fche@redhat.com> wrote:
>> > Gaurav Dhiman <dimanuec@gmail.com> writes:
>> >> [...]
>> >> Following are the logs from the Pass 5 of the run with stap -vvvt
>> >> -DDEBUG_UPROBES:
>> >>
>> >> Pass 5: starting run.
>> >> [...]
>> >> stapio:stp_main_loop:571 probe_start() returned 0
>> >> stap_uprobe_change_plus:67: +uprobe spec 0 idx 0 process uprobe-test[25763] addr 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>> >> test begin!!
>> >> test_func called!
>> >> i=0x5
>> >> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process uprobe-test[25763] reloc 0000000000400517 pp process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>> >>
>> >> The program receives a SIGSEGV signal at this point.
>> >
>> > OK, something is wrong here.  See that -uprobe line?  It means stap
>> > has for some reason determined that it's time to remove the uprobe,
>> > but that should not happen until either the script or the target
>> > program exits.
>> >
>> > This will make things more verbose, but could you try adding
>> > -DDEBUG_TASK_FINDER and -DDEBUG_TASK_FINDER_VMA to the stap
>> > command line?
>> >
>> You are right, that looks suspicious; it is actually removing the
>> probe, when it should not be doing it. Here is the more verbose
>> output:
>>
>> test_func called!
>> i=0x5
>> stap_uprobe_process_found:246: -proc pid 27237 stf ffffffffa001dce0
>> ffffffffa001dce0 path /home/gdhiman/tests/uprobe-test
>> stap_uprobe_change_minus:220: -uprobe spec 0 idx 0 process
>> uprobe-test[27237] reloc 0000000000400517 pp
>> process("/home/gdhiman/tests/uprobe-test").function("test_func@/home/gdhiman/tests/uprobe-test.c:4")
>> _stp_tf_exec_cb:29: tsk 27237:27237 , register_p: 0, process_p: 1
>
> Unless I am reading the logs wrong, I do think this is expected. The
> process gets a SIGSEGV and so uprobes is notified that it needs to clean
> up (-proc pid 27237 means process is gone).
>
>> > I meant the uprobe-test binary, just to see what instructions were
>> > in the vicinity of the test_func function.  Just that area.
>> >
>>
>> Here it is:
>>
>> 000000000040050c <test_func>:
>>   40050c:       55                      push   %rbp
>>   40050d:       48 89 e5                mov    %rsp,%rbp
>>   400510:       48 83 ec 10             sub    $0x10,%rsp
>>   400514:       89 7d fc                mov    %edi,-0x4(%rbp)
>>   400517:       8b 75 fc                mov    -0x4(%rbp),%esi
>>   40051a:       bf 3c 06 40 00          mov    $0x40063c,%edi
>>   40051f:       b8 00 00 00 00          mov    $0x0,%eax
>>   400524:       e8 cf fe ff ff          callq  4003f8 <printf@plt>
>>   400529:       8b 45 fc                mov    -0x4(%rbp),%eax
>>   40052c:       c9                      leaveq
>>   40052d:       c3                      retq
>
> That does look OK, even though it looks different from my local build:
>
> Dump of assembler code for function test_func:
>   0x080483d0 <+0>:     push   %ebp
>   0x080483d1 <+1>:     mov    %esp,%ebp
>   0x080483d3 <+3>:     push   %ebx
>   0x080483d4 <+4>:     sub    $0x14,%esp
>   0x080483d7 <+7>:     mov    0x8(%ebp),%ebx
>   0x080483da <+10>:    movl   $0x80484f4,(%esp)
>   0x080483e1 <+17>:    mov    %ebx,0x4(%esp)
>   0x080483e5 <+21>:    call   0x80482f4 <printf@plt>
>   0x080483ea <+26>:    mov    %ebx,%eax
>   0x080483ec <+28>:    add    $0x14,%esp
>   0x080483ef <+31>:    pop    %ebx
>   0x080483f0 <+32>:    pop    %ebp
>   0x080483f1 <+33>:    ret
> End of assembler dump.
>
> What compiler and flags did you use? Here gcc version 4.4.4 20100503
> (Red Hat 4.4.4-2) with -g -O2.
>

I am using gcc 4.4.3 and using -g -O2 as well.

> If possible could you set ulimit -c unlimited and catch the core file of
> the program and give the disassembly from test_func in the core? Maybe
> the breakpoint instruction in there was misplaced?

I will try to send this tomorrow.

Thanks,
-Gaurav