* Puzzling output of stp script
[not found] <CAO_gTC6yXVN-6a-aj6YFy4Z_7wGaMRzbHTWWWdQOyWgD=g0rOQ@mail.gmail.com>
@ 2011-12-24 19:14 ` contemplating zombie
2011-12-24 22:56 ` Adrien Kunysz
2011-12-25 11:07 ` Josh Stone
0 siblings, 2 replies; 6+ messages in thread
From: contemplating zombie @ 2011-12-24 19:14 UTC (permalink / raw)
To: systemtap
Hi,
I am new to systemtap and I was trying out following example script
given in the documentation:
probe kernel.function("*@net/socket.c") {
printf ("%s -> %s\n", thread_indent(1), probefunc())
}
probe kernel.function("*@net/socket.c").return {
printf ("%s <- %s\n", thread_indent(-1), probefunc())
}
I sshed into a remote machine and executed it. What I see is that the
stack frames just keep on growing to right and do not return. Won't
that cause a stack overflow eventually?
Here is the output:
root@ubuntu:~# touch t.stp
root@ubuntu:~# emacs -nw t.stp
root@ubuntu:~# stap t.stp
0 sshd(804): -> sock_poll
11 sshd(804): <- sock_poll
0 sshd(804): -> sock_aio_read
2 sshd(804): -> alloc_sock_iocb
3 sshd(804): <- alloc_sock_iocb
5 sshd(804): -> do_sock_read
7 sshd(804): -> __sock_recvmsg
9 sshd(804): -> __sock_recvmsg_nosec
15 sshd(804): <- sock_aio_read
32 sshd(804): -> sock_poll
34 sshd(804): <- sock_poll
44 sshd(804): -> sock_poll
46 sshd(804): <- sock_poll
12636 sshd(804): -> sock_poll
12644 sshd(804): <- sock_poll
12678 sshd(804): -> sock_poll
12683 sshd(804): <- sock_poll
12692 sshd(804): -> sock_aio_write
12696 sshd(804): -> alloc_sock_iocb
12700 sshd(804): <- alloc_sock_iocb
12704 sshd(804): -> do_sock_write
12711 sshd(804): -> __sock_sendmsg
12763 sshd(804): <- sock_aio_write
12773 sshd(804): -> sock_poll
12775 sshd(804): <- sock_poll
162634 sshd(804): -> sock_poll
162642 sshd(804): <- sock_poll
162680 sshd(804): -> sock_poll
162683 sshd(804): <- sock_poll
162688 sshd(804): -> sock_aio_write
162690 sshd(804): -> alloc_sock_iocb
162692 sshd(804): <- alloc_sock_iocb
162693 sshd(804): -> do_sock_write
162695 sshd(804): -> __sock_sendmsg
162770 sshd(804): <- sock_aio_write
162777 sshd(804): -> sock_poll
162780 sshd(804): <- sock_poll
202760 sshd(804): -> sock_poll
202765 sshd(804): <- sock_poll
202774 sshd(804): -> sock_aio_read
202776 sshd(804): -> alloc_sock_iocb
202778 sshd(804): <- alloc_sock_iocb
202780 sshd(804): -> do_sock_read
202782 sshd(804): -> __sock_recvmsg
202784 sshd(804): -> __sock_recvmsg_nosec
202788 sshd(804): <- sock_aio_read
202796 sshd(804): -> sock_poll
202799 sshd(804): <- sock_poll
202807 sshd(804): -> sock_poll
202810 sshd(804): <- sock_poll
232494 sshd(804): -> sock_poll
232503 sshd(804): <- sock_poll
232535 sshd(804): -> sock_poll
232540 sshd(804): <- sock_poll
232550 sshd(804): -> sock_aio_write
232555 sshd(804): -> alloc_sock_iocb
232559 sshd(804): <- alloc_sock_iocb
232564 sshd(804): -> do_sock_write
232569 sshd(804): -> __sock_sendmsg
232648 sshd(804): <- sock_aio_write
232656 sshd(804): -> sock_poll
232659 sshd(804): <- sock_poll
362500 sshd(804): -> sock_poll
362509 sshd(804): <- sock_poll
362576 sshd(804): -> sock_poll
362579 sshd(804): <- sock_poll
362584 sshd(804): -> sock_aio_write
362586 sshd(804): -> alloc_sock_iocb
362588 sshd(804): <- alloc_sock_iocb
362591 sshd(804): -> do_sock_write
362593 sshd(804): -> __sock_sendmsg
362655 sshd(804): <- sock_aio_write
362663 sshd(804): -> sock_poll
362666 sshd(804): <- sock_poll
479663 sshd(804): -> sock_poll
479668 sshd(804): <- sock_poll
479677 sshd(804): -> sock_aio_read
479679 sshd(804): -> alloc_sock_iocb
479682 sshd(804): <- alloc_sock_iocb
479684 sshd(804): -> do_sock_read
479686 sshd(804): -> __sock_recvmsg
479689 sshd(804): -> __sock_recvmsg_nosec
479693 sshd(804): <- sock_aio_read
479702 sshd(804): -> sock_poll
479705 sshd(804): <- sock_poll
479713 sshd(804): -> sock_poll
479716 sshd(804): <- sock_poll
492567 sshd(804): -> sock_poll
492575 sshd(804): <- sock_poll
492592 sshd(804): -> sock_poll
492595 sshd(804): <- sock_poll
492599 sshd(804): -> sock_aio_write
492602 sshd(804): -> alloc_sock_iocb
492605 sshd(804): <- alloc_sock_iocb
492607 sshd(804): -> do_sock_write
492610 sshd(804): -> __sock_sendmsg
492651 sshd(804): <- sock_aio_write
492662 sshd(804): -> sock_poll
492666 sshd(804): <- sock_poll
562635 sshd(804): -> sock_poll
562645 sshd(804): <- sock_poll
562692 sshd(804): -> sock_poll
562696 sshd(804): <- sock_poll
562701 sshd(804): -> sock_aio_write
562704 sshd(804): -> alloc_sock_iocb
562706 sshd(804): <- alloc_sock_iocb
562709 sshd(804): -> do_sock_write
562712 sshd(804): -> __sock_sendmsg
562821 sshd(804): <- sock_aio_write
562830 sshd(804): -> sock_poll
562834 sshd(804): <- sock_poll
762649 sshd(804): -> sock_poll
762659 sshd(804): <- sock_poll
762687 sshd(804): -> sock_poll
762690 sshd(804): <- sock_poll
762695 sshd(804): -> sock_aio_write
762698 sshd(804): -> alloc_sock_iocb
762701 sshd(804): <- alloc_sock_iocb
762704 sshd(804): -> do_sock_write
762706 sshd(804): -> __sock_sendmsg
762749 sshd(804): <- sock_aio_write
762757 sshd(804): -> sock_poll
762761 sshd(804): <- sock_poll
962447 sshd(804): -> sock_poll
962458 sshd(804): <- sock_poll
962525 sshd(804): -> sock_poll
962534 sshd(804): <- sock_poll
962548 sshd(804): -> sock_aio_write
962552 sshd(804): -> alloc_sock_iocb
962555 sshd(804): <- alloc_sock_iocb
962558 sshd(804): -> do_sock_write
962561 sshd(804): -> __sock_sendmsg
962643 sshd(804): <- sock_aio_write
962652 sshd(804): -> sock_poll
962656 sshd(804): <- sock_poll
1162558 sshd(804): -> sock_poll
1162563 sshd(804): <- sock_poll
1162587 sshd(804): -> sock_poll
1162591 sshd(804): <- sock_poll
1162596 sshd(804): -> sock_aio_write
1162600 sshd(804): -> alloc_sock_iocb
1162603 sshd(804): <- alloc_sock_iocb
1162606 sshd(804): -> do_sock_write
1162609 sshd(804): -> __sock_sendmsg
1162652 sshd(804): <- sock_aio_write
1162664 sshd(804): -> sock_poll
1162668 sshd(804): <- sock_poll
1362636 sshd(804): -> sock_poll
1362647 sshd(804): <- sock_poll
1362684 sshd(804): -> sock_poll
1362688 sshd(804): <- sock_poll
1362693 sshd(804): -> sock_aio_write
1362697 sshd(804): -> alloc_sock_iocb
1362700 sshd(804): <- alloc_sock_iocb
1362704 sshd(804): -> do_sock_write
1362707 sshd(804): -> __sock_sendmsg
1362788 sshd(804): <- sock_aio_write
1362801 sshd(804): -> sock_poll
1362805 sshd(804): <- sock_poll
1562553 sshd(804): -> sock_poll
1562565 sshd(804): <- sock_poll
1562617 sshd(804): -> sock_poll
1562626 sshd(804): <- sock_poll
1562639 sshd(804): -> sock_aio_write
1562643 sshd(804): -> alloc_sock_iocb
1562646 sshd(804): <- alloc_sock_iocb
1562650 sshd(804): -> do_sock_write
1562653 sshd(804): -> __sock_sendmsg
1562696 sshd(804): <- sock_aio_write
1562708 sshd(804): -> sock_poll
1562713 sshd(804): <- sock_poll
1762582 sshd(804): -> sock_poll
1762588 sshd(804): <- sock_poll
1762614 sshd(804): -> sock_poll
1762618 sshd(804): <- sock_poll
1762624 sshd(804): -> sock_aio_write
1762627 sshd(804): -> alloc_sock_iocb
1762631 sshd(804): <- alloc_sock_iocb
1762635 sshd(804): -> do_sock_write
1762638 sshd(804): -> __sock_sendmsg
1762681 sshd(804): <- sock_aio_write
1762692 sshd(804): -> sock_poll
1762696 sshd(804): <- sock_poll
1962573 sshd(804): -> sock_poll
1962579 sshd(804): <- sock_poll
1962605 sshd(804): -> sock_poll
1962609 sshd(804): <- sock_poll
1962615 sshd(804): -> sock_aio_write
1962619 sshd(804): -> alloc_sock_iocb
1962623 sshd(804): <- alloc_sock_iocb
1962627 sshd(804): -> do_sock_write
1962631 sshd(804): -> __sock_sendmsg
1962714 sshd(804): <- sock_aio_write
1962724 sshd(804): -> sock_poll
1962729 sshd(804): <- sock_poll
2162633 sshd(804): -> sock_poll
2162646 sshd(804): <- sock_poll
2162683 sshd(804): -> sock_poll
2162688 sshd(804): <- sock_poll
2162694 sshd(804): -> sock_aio_write
2162698 sshd(804): -> alloc_sock_iocb
2162702 sshd(804): <- alloc_sock_iocb
2162706 sshd(804): -> do_sock_write
2162710 sshd(804): -> __sock_sendmsg
2162789 sshd(804): <- sock_aio_write
2162802 sshd(804): -> sock_poll
2162807 sshd(804): <- sock_poll
2362633 sshd(804): -> sock_poll
2362646 sshd(804): <- sock_poll
2362684 sshd(804): -> sock_poll
2362688 sshd(804): <- sock_poll
2362695 sshd(804): -> sock_aio_write
2362699 sshd(804): -> alloc_sock_iocb
2362703 sshd(804): <- alloc_sock_iocb
2362707 sshd(804): -> do_sock_write
2362711 sshd(804): -> __sock_sendmsg
2362757 sshd(804): <- sock_aio_write
2362767 sshd(804): -> sock_poll
2362772 sshd(804): <- sock_poll
2562462 sshd(804): -> sock_poll
2562479 sshd(804): <- sock_poll
2562522 sshd(804): -> sock_poll
2562527 sshd(804): <- sock_poll
2562534 sshd(804): -> sock_aio_write
2562538 sshd(804): -> alloc_sock_iocb
2562542 sshd(804): <- alloc_sock_iocb
2562547 sshd(804): -> do_sock_write
2562551 sshd(804): -> __sock_sendmsg
2562595 sshd(804): <- sock_aio_write
2562605 sshd(804): -> sock_poll
2562612 sshd(804): <- sock_poll
2762583 sshd(804): -> sock_poll
2762596 sshd(804): <- sock_poll
2762638 sshd(804): -> sock_poll
2762643 sshd(804): <- sock_poll
2762649 sshd(804): -> sock_aio_write
2762654 sshd(804): -> alloc_sock_iocb
2762658 sshd(804): <- alloc_sock_iocb
2762663 sshd(804): -> do_sock_write
2762667 sshd(804): -> __sock_sendmsg
2762751 sshd(804): <- sock_aio_write
2762761 sshd(804): -> sock_poll
2762766 sshd(804): <- sock_poll
2962386 sshd(804): -> sock_poll
2962392 sshd(804): <- sock_poll
2962420 sshd(804): -> sock_poll
2962425 sshd(804): <- sock_poll
2962432 sshd(804): -> sock_aio_write
2962437 sshd(804): ->
alloc_sock_iocb
2962442 sshd(804): <-
alloc_sock_iocb
2962446 sshd(804): -> do_sock_write
2962451 sshd(804): ->
__sock_sendmsg
2962496 sshd(804): <-
sock_aio_write
2962510 sshd(804): -> sock_poll
2962515 sshd(804): <- sock_poll
^C3162600 sshd(804): -> sock_poll
3162615 sshd(804): <- sock_poll
3162648 sshd(804): -> sock_poll
3162653 sshd(804): <- sock_poll
3162660 sshd(804): ->
sock_aio_write
3162665 sshd(804): ->
alloc_sock_iocb
3162670 sshd(804): <-
alloc_sock_iocb
3162675 sshd(804): ->
do_sock_write
3162679 sshd(804): ->
__sock_sendmsg
3162765 sshd(804): <-
sock_aio_write
3162776 sshd(804): -> sock_poll
3162782 sshd(804): <- sock_poll
3184606 sshd(804): -> sock_poll
3184613 sshd(804): <- sock_poll
3184624 sshd(804): ->
sock_aio_read
3184630 sshd(804): ->
alloc_sock_iocb
3184635 sshd(804): <-
alloc_sock_iocb
3184640 sshd(804): ->
do_sock_read
3184644 sshd(804): ->
__sock_recvmsg
3184649 sshd(804):
-> __sock_recvmsg_nosec
3184657 sshd(804):
<- sock_aio_read
3184668 sshd(804):
-> sock_poll
3184674 sshd(804):
<- sock_poll
3184688 sshd(804):
-> sock_poll
3184693 sshd(804):
<- sock_poll
Pass 5: run failed. Try again with another '--vp 00001' option.
root@ubuntu:~#
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Puzzling output of stp script
2011-12-24 19:14 ` Puzzling output of stp script contemplating zombie
@ 2011-12-24 22:56 ` Adrien Kunysz
2011-12-25 5:56 ` contemplating zombie
2011-12-25 11:07 ` Josh Stone
1 sibling, 1 reply; 6+ messages in thread
From: Adrien Kunysz @ 2011-12-24 22:56 UTC (permalink / raw)
To: contemplating zombie; +Cc: systemtap
[-- Attachment #1: Type: text/plain, Size: 18913 bytes --]
On Sat, Dec 24, 2011 at 01:31:21PM -0500, contemplating zombie wrote:
> I am new to systemtap and I was trying out following example script
> given in the documentation:
>
> probe kernel.function("*@net/socket.c") {
> printf ("%s -> %s\n", thread_indent(1), probefunc())
> }
>
> probe kernel.function("*@net/socket.c").return {
> printf ("%s <- %s\n", thread_indent(-1), probefunc())
> }
>
> I sshed into a remote machine and executed it. What I see is that the
> stack frames just keep on growing to right and do not return. Won't
> that cause a stack overflow eventually?
Rather than a stack overflow it is possible (and probably more likely)
that SystemTap is missing some return probes somehow.
> Here is the output:
>
> root@ubuntu:~# touch t.stp
> root@ubuntu:~# emacs -nw t.stp
> root@ubuntu:~# stap t.stp
>
> 0 sshd(804): -> sock_poll
> 11 sshd(804): <- sock_poll
> 0 sshd(804): -> sock_aio_read
> 2 sshd(804): -> alloc_sock_iocb
> 3 sshd(804): <- alloc_sock_iocb
> 5 sshd(804): -> do_sock_read
> 7 sshd(804): -> __sock_recvmsg
> 9 sshd(804): -> __sock_recvmsg_nosec
Notice how do_sock_read() supposedly never returns while it
should return immediately after __sock_recvmsg() (at least
in the current mainline kernel):
830 static ssize_t do_sock_read(struct msghdr *msg, struct kiocb *iocb,
831 struct file *file, const struct iovec *iov,
832 unsigned long nr_segs)
833 {
...
849 return __sock_recvmsg(iocb, sock, msg, size, msg->msg_flags);
850 }
I guess there is some kind of optimisation that interacts poorly with
debug symbols and/or the way SystemTap interpret them. Details about
the relevant object code and or stap-report output would probably help.
> 15 sshd(804): <- sock_aio_read
> 32 sshd(804): -> sock_poll
> 34 sshd(804): <- sock_poll
> 44 sshd(804): -> sock_poll
> 46 sshd(804): <- sock_poll
> 12636 sshd(804): -> sock_poll
> 12644 sshd(804): <- sock_poll
> 12678 sshd(804): -> sock_poll
> 12683 sshd(804): <- sock_poll
> 12692 sshd(804): -> sock_aio_write
> 12696 sshd(804): -> alloc_sock_iocb
> 12700 sshd(804): <- alloc_sock_iocb
> 12704 sshd(804): -> do_sock_write
> 12711 sshd(804): -> __sock_sendmsg
> 12763 sshd(804): <- sock_aio_write
> 12773 sshd(804): -> sock_poll
> 12775 sshd(804): <- sock_poll
>
> 162634 sshd(804): -> sock_poll
> 162642 sshd(804): <- sock_poll
> 162680 sshd(804): -> sock_poll
> 162683 sshd(804): <- sock_poll
> 162688 sshd(804): -> sock_aio_write
> 162690 sshd(804): -> alloc_sock_iocb
> 162692 sshd(804): <- alloc_sock_iocb
> 162693 sshd(804): -> do_sock_write
> 162695 sshd(804): -> __sock_sendmsg
> 162770 sshd(804): <- sock_aio_write
> 162777 sshd(804): -> sock_poll
> 162780 sshd(804): <- sock_poll
> 202760 sshd(804): -> sock_poll
> 202765 sshd(804): <- sock_poll
> 202774 sshd(804): -> sock_aio_read
> 202776 sshd(804): -> alloc_sock_iocb
> 202778 sshd(804): <- alloc_sock_iocb
> 202780 sshd(804): -> do_sock_read
> 202782 sshd(804): -> __sock_recvmsg
> 202784 sshd(804): -> __sock_recvmsg_nosec
> 202788 sshd(804): <- sock_aio_read
> 202796 sshd(804): -> sock_poll
> 202799 sshd(804): <- sock_poll
> 202807 sshd(804): -> sock_poll
> 202810 sshd(804): <- sock_poll
> 232494 sshd(804): -> sock_poll
> 232503 sshd(804): <- sock_poll
> 232535 sshd(804): -> sock_poll
> 232540 sshd(804): <- sock_poll
> 232550 sshd(804): -> sock_aio_write
> 232555 sshd(804): -> alloc_sock_iocb
> 232559 sshd(804): <- alloc_sock_iocb
> 232564 sshd(804): -> do_sock_write
> 232569 sshd(804): -> __sock_sendmsg
> 232648 sshd(804): <- sock_aio_write
> 232656 sshd(804): -> sock_poll
> 232659 sshd(804): <- sock_poll
>
> 362500 sshd(804): -> sock_poll
> 362509 sshd(804): <- sock_poll
> 362576 sshd(804): -> sock_poll
> 362579 sshd(804): <- sock_poll
> 362584 sshd(804): -> sock_aio_write
> 362586 sshd(804): -> alloc_sock_iocb
> 362588 sshd(804): <- alloc_sock_iocb
> 362591 sshd(804): -> do_sock_write
> 362593 sshd(804): -> __sock_sendmsg
> 362655 sshd(804): <- sock_aio_write
> 362663 sshd(804): -> sock_poll
> 362666 sshd(804): <- sock_poll
> 479663 sshd(804): -> sock_poll
> 479668 sshd(804): <- sock_poll
> 479677 sshd(804): -> sock_aio_read
> 479679 sshd(804): -> alloc_sock_iocb
> 479682 sshd(804): <- alloc_sock_iocb
> 479684 sshd(804): -> do_sock_read
> 479686 sshd(804): -> __sock_recvmsg
> 479689 sshd(804): -> __sock_recvmsg_nosec
> 479693 sshd(804): <- sock_aio_read
> 479702 sshd(804): -> sock_poll
> 479705 sshd(804): <- sock_poll
> 479713 sshd(804): -> sock_poll
> 479716 sshd(804): <- sock_poll
> 492567 sshd(804): -> sock_poll
> 492575 sshd(804): <- sock_poll
> 492592 sshd(804): -> sock_poll
> 492595 sshd(804): <- sock_poll
> 492599 sshd(804): -> sock_aio_write
> 492602 sshd(804): -> alloc_sock_iocb
> 492605 sshd(804): <- alloc_sock_iocb
> 492607 sshd(804): -> do_sock_write
> 492610 sshd(804): -> __sock_sendmsg
> 492651 sshd(804): <- sock_aio_write
> 492662 sshd(804): -> sock_poll
> 492666 sshd(804): <- sock_poll
> 562635 sshd(804): -> sock_poll
> 562645 sshd(804): <- sock_poll
> 562692 sshd(804): -> sock_poll
> 562696 sshd(804): <- sock_poll
> 562701 sshd(804): -> sock_aio_write
> 562704 sshd(804): -> alloc_sock_iocb
> 562706 sshd(804): <- alloc_sock_iocb
> 562709 sshd(804): -> do_sock_write
> 562712 sshd(804): -> __sock_sendmsg
> 562821 sshd(804): <- sock_aio_write
> 562830 sshd(804): -> sock_poll
> 562834 sshd(804): <- sock_poll
> 762649 sshd(804): -> sock_poll
> 762659 sshd(804): <- sock_poll
> 762687 sshd(804): -> sock_poll
> 762690 sshd(804): <- sock_poll
> 762695 sshd(804): -> sock_aio_write
> 762698 sshd(804): -> alloc_sock_iocb
> 762701 sshd(804): <- alloc_sock_iocb
> 762704 sshd(804): -> do_sock_write
> 762706 sshd(804): -> __sock_sendmsg
> 762749 sshd(804): <- sock_aio_write
> 762757 sshd(804): -> sock_poll
> 762761 sshd(804): <- sock_poll
> 962447 sshd(804): -> sock_poll
> 962458 sshd(804): <- sock_poll
> 962525 sshd(804): -> sock_poll
> 962534 sshd(804): <- sock_poll
> 962548 sshd(804): -> sock_aio_write
> 962552 sshd(804): -> alloc_sock_iocb
> 962555 sshd(804): <- alloc_sock_iocb
> 962558 sshd(804): -> do_sock_write
> 962561 sshd(804): -> __sock_sendmsg
> 962643 sshd(804): <- sock_aio_write
> 962652 sshd(804): -> sock_poll
> 962656 sshd(804): <- sock_poll
> 1162558 sshd(804): -> sock_poll
> 1162563 sshd(804): <- sock_poll
> 1162587 sshd(804): -> sock_poll
> 1162591 sshd(804): <- sock_poll
> 1162596 sshd(804): -> sock_aio_write
> 1162600 sshd(804): -> alloc_sock_iocb
> 1162603 sshd(804): <- alloc_sock_iocb
> 1162606 sshd(804): -> do_sock_write
> 1162609 sshd(804): -> __sock_sendmsg
> 1162652 sshd(804): <- sock_aio_write
> 1162664 sshd(804): -> sock_poll
> 1162668 sshd(804): <- sock_poll
> 1362636 sshd(804): -> sock_poll
> 1362647 sshd(804): <- sock_poll
> 1362684 sshd(804): -> sock_poll
> 1362688 sshd(804): <- sock_poll
> 1362693 sshd(804): -> sock_aio_write
> 1362697 sshd(804): -> alloc_sock_iocb
> 1362700 sshd(804): <- alloc_sock_iocb
> 1362704 sshd(804): -> do_sock_write
> 1362707 sshd(804): -> __sock_sendmsg
> 1362788 sshd(804): <- sock_aio_write
> 1362801 sshd(804): -> sock_poll
> 1362805 sshd(804): <- sock_poll
> 1562553 sshd(804): -> sock_poll
> 1562565 sshd(804): <- sock_poll
> 1562617 sshd(804): -> sock_poll
> 1562626 sshd(804): <- sock_poll
> 1562639 sshd(804): -> sock_aio_write
> 1562643 sshd(804): -> alloc_sock_iocb
> 1562646 sshd(804): <- alloc_sock_iocb
> 1562650 sshd(804): -> do_sock_write
> 1562653 sshd(804): -> __sock_sendmsg
> 1562696 sshd(804): <- sock_aio_write
> 1562708 sshd(804): -> sock_poll
> 1562713 sshd(804): <- sock_poll
> 1762582 sshd(804): -> sock_poll
> 1762588 sshd(804): <- sock_poll
> 1762614 sshd(804): -> sock_poll
> 1762618 sshd(804): <- sock_poll
> 1762624 sshd(804): -> sock_aio_write
> 1762627 sshd(804): -> alloc_sock_iocb
> 1762631 sshd(804): <- alloc_sock_iocb
> 1762635 sshd(804): -> do_sock_write
> 1762638 sshd(804): -> __sock_sendmsg
> 1762681 sshd(804): <- sock_aio_write
> 1762692 sshd(804): -> sock_poll
> 1762696 sshd(804): <- sock_poll
> 1962573 sshd(804): -> sock_poll
> 1962579 sshd(804): <- sock_poll
> 1962605 sshd(804): -> sock_poll
> 1962609 sshd(804): <- sock_poll
> 1962615 sshd(804): -> sock_aio_write
> 1962619 sshd(804): -> alloc_sock_iocb
> 1962623 sshd(804): <- alloc_sock_iocb
> 1962627 sshd(804): -> do_sock_write
> 1962631 sshd(804): -> __sock_sendmsg
> 1962714 sshd(804): <- sock_aio_write
> 1962724 sshd(804): -> sock_poll
> 1962729 sshd(804): <- sock_poll
> 2162633 sshd(804): -> sock_poll
> 2162646 sshd(804): <- sock_poll
> 2162683 sshd(804): -> sock_poll
> 2162688 sshd(804): <- sock_poll
> 2162694 sshd(804): -> sock_aio_write
> 2162698 sshd(804): -> alloc_sock_iocb
> 2162702 sshd(804): <- alloc_sock_iocb
> 2162706 sshd(804): -> do_sock_write
> 2162710 sshd(804): -> __sock_sendmsg
> 2162789 sshd(804): <- sock_aio_write
> 2162802 sshd(804): -> sock_poll
> 2162807 sshd(804): <- sock_poll
> 2362633 sshd(804): -> sock_poll
> 2362646 sshd(804): <- sock_poll
> 2362684 sshd(804): -> sock_poll
> 2362688 sshd(804): <- sock_poll
> 2362695 sshd(804): -> sock_aio_write
> 2362699 sshd(804): -> alloc_sock_iocb
> 2362703 sshd(804): <- alloc_sock_iocb
> 2362707 sshd(804): -> do_sock_write
> 2362711 sshd(804): -> __sock_sendmsg
> 2362757 sshd(804): <- sock_aio_write
> 2362767 sshd(804): -> sock_poll
> 2362772 sshd(804): <- sock_poll
> 2562462 sshd(804): -> sock_poll
> 2562479 sshd(804): <- sock_poll
> 2562522 sshd(804): -> sock_poll
> 2562527 sshd(804): <- sock_poll
> 2562534 sshd(804): -> sock_aio_write
> 2562538 sshd(804): -> alloc_sock_iocb
> 2562542 sshd(804): <- alloc_sock_iocb
> 2562547 sshd(804): -> do_sock_write
> 2562551 sshd(804): -> __sock_sendmsg
> 2562595 sshd(804): <- sock_aio_write
> 2562605 sshd(804): -> sock_poll
> 2562612 sshd(804): <- sock_poll
> 2762583 sshd(804): -> sock_poll
> 2762596 sshd(804): <- sock_poll
> 2762638 sshd(804): -> sock_poll
> 2762643 sshd(804): <- sock_poll
> 2762649 sshd(804): -> sock_aio_write
> 2762654 sshd(804): -> alloc_sock_iocb
> 2762658 sshd(804): <- alloc_sock_iocb
> 2762663 sshd(804): -> do_sock_write
> 2762667 sshd(804): -> __sock_sendmsg
> 2762751 sshd(804): <- sock_aio_write
> 2762761 sshd(804): -> sock_poll
> 2762766 sshd(804): <- sock_poll
> 2962386 sshd(804): -> sock_poll
> 2962392 sshd(804): <- sock_poll
> 2962420 sshd(804): -> sock_poll
> 2962425 sshd(804): <- sock_poll
> 2962432 sshd(804): -> sock_aio_write
> 2962437 sshd(804): ->
> alloc_sock_iocb
> 2962442 sshd(804): <-
> alloc_sock_iocb
> 2962446 sshd(804): -> do_sock_write
> 2962451 sshd(804): ->
> __sock_sendmsg
> 2962496 sshd(804): <-
> sock_aio_write
> 2962510 sshd(804): -> sock_poll
> 2962515 sshd(804): <- sock_poll
> ^C3162600 sshd(804): -> sock_poll
> 3162615 sshd(804): <- sock_poll
> 3162648 sshd(804): -> sock_poll
> 3162653 sshd(804): <- sock_poll
> 3162660 sshd(804): ->
> sock_aio_write
> 3162665 sshd(804): ->
> alloc_sock_iocb
> 3162670 sshd(804): <-
> alloc_sock_iocb
> 3162675 sshd(804): ->
> do_sock_write
> 3162679 sshd(804): ->
> __sock_sendmsg
> 3162765 sshd(804): <-
> sock_aio_write
> 3162776 sshd(804): -> sock_poll
> 3162782 sshd(804): <- sock_poll
> 3184606 sshd(804): -> sock_poll
> 3184613 sshd(804): <- sock_poll
> 3184624 sshd(804): ->
> sock_aio_read
> 3184630 sshd(804): ->
> alloc_sock_iocb
> 3184635 sshd(804): <-
> alloc_sock_iocb
> 3184640 sshd(804): ->
> do_sock_read
> 3184644 sshd(804): ->
> __sock_recvmsg
> 3184649 sshd(804):
> -> __sock_recvmsg_nosec
> 3184657 sshd(804):
> <- sock_aio_read
> 3184668 sshd(804):
> -> sock_poll
> 3184674 sshd(804):
> <- sock_poll
> 3184688 sshd(804):
> -> sock_poll
> 3184693 sshd(804):
> <- sock_poll
> Pass 5: run failed. Try again with another '--vp 00001' option.
> root@ubuntu:~#
[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Puzzling output of stp script
2011-12-24 22:56 ` Adrien Kunysz
@ 2011-12-25 5:56 ` contemplating zombie
0 siblings, 0 replies; 6+ messages in thread
From: contemplating zombie @ 2011-12-25 5:56 UTC (permalink / raw)
To: Adrien Kunysz; +Cc: systemtap
[-- Attachment #1: Type: text/plain, Size: 19382 bytes --]
Hi,
Thanks for the response. I am running a custom compiled pristine
kernel 2.6.36 on ubuntu 10.04 KVM virtual machine.
Also attaching the output of stap-report.
-ctmzb
On Sat, Dec 24, 2011 at 2:17 PM, Adrien Kunysz <adrien@kunysz.be> wrote:
> On Sat, Dec 24, 2011 at 01:31:21PM -0500, contemplating zombie wrote:
>> I am new to systemtap and I was trying out following example script
>> given in the documentation:
>>
>> probe kernel.function("*@net/socket.c") {
>> printf ("%s -> %s\n", thread_indent(1), probefunc())
>> }
>>
>> probe kernel.function("*@net/socket.c").return {
>> printf ("%s <- %s\n", thread_indent(-1), probefunc())
>> }
>>
>> I sshed into a remote machine and executed it. What I see is that the
>> stack frames just keep on growing to right and do not return. Won't
>> that cause a stack overflow eventually?
>
> Rather than a stack overflow it is possible (and probably more likely)
> that SystemTap is missing some return probes somehow.
>
>> Here is the output:
>>
>> root@ubuntu:~# touch t.stp
>> root@ubuntu:~# emacs -nw t.stp
>> root@ubuntu:~# stap t.stp
>>
>> 0 sshd(804): -> sock_poll
>> 11 sshd(804): <- sock_poll
>> 0 sshd(804): -> sock_aio_read
>> 2 sshd(804): -> alloc_sock_iocb
>> 3 sshd(804): <- alloc_sock_iocb
>> 5 sshd(804): -> do_sock_read
>> 7 sshd(804): -> __sock_recvmsg
>> 9 sshd(804): -> __sock_recvmsg_nosec
>
> Notice how do_sock_read() supposedly never returns while it
> should return immediately after __sock_recvmsg() (at least
> in the current mainline kernel):
>
> 830 static ssize_t do_sock_read(struct msghdr *msg, struct kiocb *iocb,
> 831 struct file *file, const struct iovec *iov,
> 832 unsigned long nr_segs)
> 833 {
> ...
> 849 return __sock_recvmsg(iocb, sock, msg, size, msg->msg_flags);
> 850 }
>
> I guess there is some kind of optimisation that interacts poorly with
> debug symbols and/or the way SystemTap interpret them. Details about
> the relevant object code and or stap-report output would probably help.
>
>> 15 sshd(804): <- sock_aio_read
>> 32 sshd(804): -> sock_poll
>> 34 sshd(804): <- sock_poll
>> 44 sshd(804): -> sock_poll
>> 46 sshd(804): <- sock_poll
>> 12636 sshd(804): -> sock_poll
>> 12644 sshd(804): <- sock_poll
>> 12678 sshd(804): -> sock_poll
>> 12683 sshd(804): <- sock_poll
>> 12692 sshd(804): -> sock_aio_write
>> 12696 sshd(804): -> alloc_sock_iocb
>> 12700 sshd(804): <- alloc_sock_iocb
>> 12704 sshd(804): -> do_sock_write
>> 12711 sshd(804): -> __sock_sendmsg
>> 12763 sshd(804): <- sock_aio_write
>> 12773 sshd(804): -> sock_poll
>> 12775 sshd(804): <- sock_poll
>>
>> 162634 sshd(804): -> sock_poll
>> 162642 sshd(804): <- sock_poll
>> 162680 sshd(804): -> sock_poll
>> 162683 sshd(804): <- sock_poll
>> 162688 sshd(804): -> sock_aio_write
>> 162690 sshd(804): -> alloc_sock_iocb
>> 162692 sshd(804): <- alloc_sock_iocb
>> 162693 sshd(804): -> do_sock_write
>> 162695 sshd(804): -> __sock_sendmsg
>> 162770 sshd(804): <- sock_aio_write
>> 162777 sshd(804): -> sock_poll
>> 162780 sshd(804): <- sock_poll
>> 202760 sshd(804): -> sock_poll
>> 202765 sshd(804): <- sock_poll
>> 202774 sshd(804): -> sock_aio_read
>> 202776 sshd(804): -> alloc_sock_iocb
>> 202778 sshd(804): <- alloc_sock_iocb
>> 202780 sshd(804): -> do_sock_read
>> 202782 sshd(804): -> __sock_recvmsg
>> 202784 sshd(804): -> __sock_recvmsg_nosec
>> 202788 sshd(804): <- sock_aio_read
>> 202796 sshd(804): -> sock_poll
>> 202799 sshd(804): <- sock_poll
>> 202807 sshd(804): -> sock_poll
>> 202810 sshd(804): <- sock_poll
>> 232494 sshd(804): -> sock_poll
>> 232503 sshd(804): <- sock_poll
>> 232535 sshd(804): -> sock_poll
>> 232540 sshd(804): <- sock_poll
>> 232550 sshd(804): -> sock_aio_write
>> 232555 sshd(804): -> alloc_sock_iocb
>> 232559 sshd(804): <- alloc_sock_iocb
>> 232564 sshd(804): -> do_sock_write
>> 232569 sshd(804): -> __sock_sendmsg
>> 232648 sshd(804): <- sock_aio_write
>> 232656 sshd(804): -> sock_poll
>> 232659 sshd(804): <- sock_poll
>>
>> 362500 sshd(804): -> sock_poll
>> 362509 sshd(804): <- sock_poll
>> 362576 sshd(804): -> sock_poll
>> 362579 sshd(804): <- sock_poll
>> 362584 sshd(804): -> sock_aio_write
>> 362586 sshd(804): -> alloc_sock_iocb
>> 362588 sshd(804): <- alloc_sock_iocb
>> 362591 sshd(804): -> do_sock_write
>> 362593 sshd(804): -> __sock_sendmsg
>> 362655 sshd(804): <- sock_aio_write
>> 362663 sshd(804): -> sock_poll
>> 362666 sshd(804): <- sock_poll
>> 479663 sshd(804): -> sock_poll
>> 479668 sshd(804): <- sock_poll
>> 479677 sshd(804): -> sock_aio_read
>> 479679 sshd(804): -> alloc_sock_iocb
>> 479682 sshd(804): <- alloc_sock_iocb
>> 479684 sshd(804): -> do_sock_read
>> 479686 sshd(804): -> __sock_recvmsg
>> 479689 sshd(804): -> __sock_recvmsg_nosec
>> 479693 sshd(804): <- sock_aio_read
>> 479702 sshd(804): -> sock_poll
>> 479705 sshd(804): <- sock_poll
>> 479713 sshd(804): -> sock_poll
>> 479716 sshd(804): <- sock_poll
>> 492567 sshd(804): -> sock_poll
>> 492575 sshd(804): <- sock_poll
>> 492592 sshd(804): -> sock_poll
>> 492595 sshd(804): <- sock_poll
>> 492599 sshd(804): -> sock_aio_write
>> 492602 sshd(804): -> alloc_sock_iocb
>> 492605 sshd(804): <- alloc_sock_iocb
>> 492607 sshd(804): -> do_sock_write
>> 492610 sshd(804): -> __sock_sendmsg
>> 492651 sshd(804): <- sock_aio_write
>> 492662 sshd(804): -> sock_poll
>> 492666 sshd(804): <- sock_poll
>> 562635 sshd(804): -> sock_poll
>> 562645 sshd(804): <- sock_poll
>> 562692 sshd(804): -> sock_poll
>> 562696 sshd(804): <- sock_poll
>> 562701 sshd(804): -> sock_aio_write
>> 562704 sshd(804): -> alloc_sock_iocb
>> 562706 sshd(804): <- alloc_sock_iocb
>> 562709 sshd(804): -> do_sock_write
>> 562712 sshd(804): -> __sock_sendmsg
>> 562821 sshd(804): <- sock_aio_write
>> 562830 sshd(804): -> sock_poll
>> 562834 sshd(804): <- sock_poll
>> 762649 sshd(804): -> sock_poll
>> 762659 sshd(804): <- sock_poll
>> 762687 sshd(804): -> sock_poll
>> 762690 sshd(804): <- sock_poll
>> 762695 sshd(804): -> sock_aio_write
>> 762698 sshd(804): -> alloc_sock_iocb
>> 762701 sshd(804): <- alloc_sock_iocb
>> 762704 sshd(804): -> do_sock_write
>> 762706 sshd(804): -> __sock_sendmsg
>> 762749 sshd(804): <- sock_aio_write
>> 762757 sshd(804): -> sock_poll
>> 762761 sshd(804): <- sock_poll
>> 962447 sshd(804): -> sock_poll
>> 962458 sshd(804): <- sock_poll
>> 962525 sshd(804): -> sock_poll
>> 962534 sshd(804): <- sock_poll
>> 962548 sshd(804): -> sock_aio_write
>> 962552 sshd(804): -> alloc_sock_iocb
>> 962555 sshd(804): <- alloc_sock_iocb
>> 962558 sshd(804): -> do_sock_write
>> 962561 sshd(804): -> __sock_sendmsg
>> 962643 sshd(804): <- sock_aio_write
>> 962652 sshd(804): -> sock_poll
>> 962656 sshd(804): <- sock_poll
>> 1162558 sshd(804): -> sock_poll
>> 1162563 sshd(804): <- sock_poll
>> 1162587 sshd(804): -> sock_poll
>> 1162591 sshd(804): <- sock_poll
>> 1162596 sshd(804): -> sock_aio_write
>> 1162600 sshd(804): -> alloc_sock_iocb
>> 1162603 sshd(804): <- alloc_sock_iocb
>> 1162606 sshd(804): -> do_sock_write
>> 1162609 sshd(804): -> __sock_sendmsg
>> 1162652 sshd(804): <- sock_aio_write
>> 1162664 sshd(804): -> sock_poll
>> 1162668 sshd(804): <- sock_poll
>> 1362636 sshd(804): -> sock_poll
>> 1362647 sshd(804): <- sock_poll
>> 1362684 sshd(804): -> sock_poll
>> 1362688 sshd(804): <- sock_poll
>> 1362693 sshd(804): -> sock_aio_write
>> 1362697 sshd(804): -> alloc_sock_iocb
>> 1362700 sshd(804): <- alloc_sock_iocb
>> 1362704 sshd(804): -> do_sock_write
>> 1362707 sshd(804): -> __sock_sendmsg
>> 1362788 sshd(804): <- sock_aio_write
>> 1362801 sshd(804): -> sock_poll
>> 1362805 sshd(804): <- sock_poll
>> 1562553 sshd(804): -> sock_poll
>> 1562565 sshd(804): <- sock_poll
>> 1562617 sshd(804): -> sock_poll
>> 1562626 sshd(804): <- sock_poll
>> 1562639 sshd(804): -> sock_aio_write
>> 1562643 sshd(804): -> alloc_sock_iocb
>> 1562646 sshd(804): <- alloc_sock_iocb
>> 1562650 sshd(804): -> do_sock_write
>> 1562653 sshd(804): -> __sock_sendmsg
>> 1562696 sshd(804): <- sock_aio_write
>> 1562708 sshd(804): -> sock_poll
>> 1562713 sshd(804): <- sock_poll
>> 1762582 sshd(804): -> sock_poll
>> 1762588 sshd(804): <- sock_poll
>> 1762614 sshd(804): -> sock_poll
>> 1762618 sshd(804): <- sock_poll
>> 1762624 sshd(804): -> sock_aio_write
>> 1762627 sshd(804): -> alloc_sock_iocb
>> 1762631 sshd(804): <- alloc_sock_iocb
>> 1762635 sshd(804): -> do_sock_write
>> 1762638 sshd(804): -> __sock_sendmsg
>> 1762681 sshd(804): <- sock_aio_write
>> 1762692 sshd(804): -> sock_poll
>> 1762696 sshd(804): <- sock_poll
>> 1962573 sshd(804): -> sock_poll
>> 1962579 sshd(804): <- sock_poll
>> 1962605 sshd(804): -> sock_poll
>> 1962609 sshd(804): <- sock_poll
>> 1962615 sshd(804): -> sock_aio_write
>> 1962619 sshd(804): -> alloc_sock_iocb
>> 1962623 sshd(804): <- alloc_sock_iocb
>> 1962627 sshd(804): -> do_sock_write
>> 1962631 sshd(804): -> __sock_sendmsg
>> 1962714 sshd(804): <- sock_aio_write
>> 1962724 sshd(804): -> sock_poll
>> 1962729 sshd(804): <- sock_poll
>> 2162633 sshd(804): -> sock_poll
>> 2162646 sshd(804): <- sock_poll
>> 2162683 sshd(804): -> sock_poll
>> 2162688 sshd(804): <- sock_poll
>> 2162694 sshd(804): -> sock_aio_write
>> 2162698 sshd(804): -> alloc_sock_iocb
>> 2162702 sshd(804): <- alloc_sock_iocb
>> 2162706 sshd(804): -> do_sock_write
>> 2162710 sshd(804): -> __sock_sendmsg
>> 2162789 sshd(804): <- sock_aio_write
>> 2162802 sshd(804): -> sock_poll
>> 2162807 sshd(804): <- sock_poll
>> 2362633 sshd(804): -> sock_poll
>> 2362646 sshd(804): <- sock_poll
>> 2362684 sshd(804): -> sock_poll
>> 2362688 sshd(804): <- sock_poll
>> 2362695 sshd(804): -> sock_aio_write
>> 2362699 sshd(804): -> alloc_sock_iocb
>> 2362703 sshd(804): <- alloc_sock_iocb
>> 2362707 sshd(804): -> do_sock_write
>> 2362711 sshd(804): -> __sock_sendmsg
>> 2362757 sshd(804): <- sock_aio_write
>> 2362767 sshd(804): -> sock_poll
>> 2362772 sshd(804): <- sock_poll
>> 2562462 sshd(804): -> sock_poll
>> 2562479 sshd(804): <- sock_poll
>> 2562522 sshd(804): -> sock_poll
>> 2562527 sshd(804): <- sock_poll
>> 2562534 sshd(804): -> sock_aio_write
>> 2562538 sshd(804): -> alloc_sock_iocb
>> 2562542 sshd(804): <- alloc_sock_iocb
>> 2562547 sshd(804): -> do_sock_write
>> 2562551 sshd(804): -> __sock_sendmsg
>> 2562595 sshd(804): <- sock_aio_write
>> 2562605 sshd(804): -> sock_poll
>> 2562612 sshd(804): <- sock_poll
>> 2762583 sshd(804): -> sock_poll
>> 2762596 sshd(804): <- sock_poll
>> 2762638 sshd(804): -> sock_poll
>> 2762643 sshd(804): <- sock_poll
>> 2762649 sshd(804): -> sock_aio_write
>> 2762654 sshd(804): -> alloc_sock_iocb
>> 2762658 sshd(804): <- alloc_sock_iocb
>> 2762663 sshd(804): -> do_sock_write
>> 2762667 sshd(804): -> __sock_sendmsg
>> 2762751 sshd(804): <- sock_aio_write
>> 2762761 sshd(804): -> sock_poll
>> 2762766 sshd(804): <- sock_poll
>> 2962386 sshd(804): -> sock_poll
>> 2962392 sshd(804): <- sock_poll
>> 2962420 sshd(804): -> sock_poll
>> 2962425 sshd(804): <- sock_poll
>> 2962432 sshd(804): -> sock_aio_write
>> 2962437 sshd(804): ->
>> alloc_sock_iocb
>> 2962442 sshd(804): <-
>> alloc_sock_iocb
>> 2962446 sshd(804): -> do_sock_write
>> 2962451 sshd(804): ->
>> __sock_sendmsg
>> 2962496 sshd(804): <-
>> sock_aio_write
>> 2962510 sshd(804): -> sock_poll
>> 2962515 sshd(804): <- sock_poll
>> ^C3162600 sshd(804): -> sock_poll
>> 3162615 sshd(804): <- sock_poll
>> 3162648 sshd(804): -> sock_poll
>> 3162653 sshd(804): <- sock_poll
>> 3162660 sshd(804): ->
>> sock_aio_write
>> 3162665 sshd(804): ->
>> alloc_sock_iocb
>> 3162670 sshd(804): <-
>> alloc_sock_iocb
>> 3162675 sshd(804): ->
>> do_sock_write
>> 3162679 sshd(804): ->
>> __sock_sendmsg
>> 3162765 sshd(804): <-
>> sock_aio_write
>> 3162776 sshd(804): -> sock_poll
>> 3162782 sshd(804): <- sock_poll
>> 3184606 sshd(804): -> sock_poll
>> 3184613 sshd(804): <- sock_poll
>> 3184624 sshd(804): ->
>> sock_aio_read
>> 3184630 sshd(804): ->
>> alloc_sock_iocb
>> 3184635 sshd(804): <-
>> alloc_sock_iocb
>> 3184640 sshd(804): ->
>> do_sock_read
>> 3184644 sshd(804): ->
>> __sock_recvmsg
>> 3184649 sshd(804):
>> -> __sock_recvmsg_nosec
>> 3184657 sshd(804):
>> <- sock_aio_read
>> 3184668 sshd(804):
>> -> sock_poll
>> 3184674 sshd(804):
>> <- sock_poll
>> 3184688 sshd(804):
>> -> sock_poll
>> 3184693 sshd(804):
>> <- sock_poll
>> Pass 5: run failed. Try again with another '--vp 00001' option.
>> root@ubuntu:~#
>
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.10 (GNU/Linux)
>
> iEYEARECAAYFAk72JS4ACgkQKLX03ZSPZGwWewCgj5Uzz4nMlHeFNzzkK6cPdQCH
> q5YAn1EpCJ7TsC2f8iZumRg+LDzF/uW4
> =9ChX
> -----END PGP SIGNATURE-----
>
[-- Attachment #2: stap-report.out --]
[-- Type: application/octet-stream, Size: 5544 bytes --]
== stap -V ==
SystemTap translator/driver (version 1.0/0.143 Debian version 1.0-2)
Copyright (C) 2005-2009 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
== which stap ==
/usr/bin/stap
== locate --regex '/stap(run)?$' | xargs ls -ald ==
sh: locate: not found
drwx------ 8 root root 4096 2011-12-24 22:52 .
== printenv | egrep '^PATH=|^LD_LIBRARY_PATH=|^SYSTEMTAP_.*=|^XDG_DATA.*=' ==
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games
== stap -vv -p4 -e 'probe begin {exit()}' ==
SystemTap translator/driver (version 1.0/0.143 Debian version 1.0-2)
Copyright (C) 2005-2009 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
Session arch: x86_64 release: 2.6.36-custom
Created temporary directory "/tmp/staphGYd5R"
Searched '/usr/share/systemtap/tapset/x86_64/*.stp', found 3
Searched '/usr/share/systemtap/tapset/*.stp', found 56
Pass 1: parsed user script and 59 library script(s) in 80usr/10sys/97real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 embed(s), 0 global(s) in 0usr/0sys/3real ms.
Pass 3: using cached /root/.systemtap/cache/c5/stapconf_c5ad302dc003e3e6375caf18f4954e1f_473.h
/root/.systemtap/cache/fa/stap_fa1eee685d3cb11f72b4566f47ad3060_673.ko
Pass 3: using cached /root/.systemtap/cache/fa/stap_fa1eee685d3cb11f72b4566f47ad3060_673.c
Pass 4: using cached /root/.systemtap/cache/fa/stap_fa1eee685d3cb11f72b4566f47ad3060_673.ko
Running rm -rf /tmp/staphGYd5R
== gcc -v ==
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Ubuntu 4.4.3-4ubuntu5' --with-bugurl=file:///usr/share/doc/gcc-4.4/README.Bugs --enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr --enable-shared --enable-multiarch --enable-linker-build-id --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.4 --program-suffix=-4.4 --enable-nls --enable-clocale=gnu --enable-libstdcxx-debug --enable-plugin --enable-objc-gc --disable-werror --with-arch-32=i486 --with-tune=generic --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5)
== uname -a ==
Linux ubuntu 2.6.36-custom #1 SMP Thu Dec 15 20:53:34 UTC 2011 x86_64 GNU/Linux
== dmesg | egrep 'stap|systemtap' | tail -n 10 ==
== cat /proc/cpuinfo | egrep 'processor|vendor_id|model name' ==
processor : 0
vendor_id : GenuineIntel
model name : QEMU Virtual CPU version 0.12.5
processor : 1
vendor_id : GenuineIntel
model name : QEMU Virtual CPU version 0.12.5
processor : 2
vendor_id : GenuineIntel
model name : QEMU Virtual CPU version 0.12.5
processor : 3
vendor_id : GenuineIntel
model name : QEMU Virtual CPU version 0.12.5
== dpkg --list | egrep 'systemtap|elfutils|kernel|gcc' | awk '{print $2,$3}' | sort ==
gcc 4:4.4.3-1ubuntu1
gcc-4.4 4.4.3-4ubuntu5
gcc-4.4-base 4.4.3-4ubuntu5
kernel-package 12.032
libdrm2 2.4.18-1ubuntu3
libdrm-intel1 2.4.18-1ubuntu3
libgcc1 1:4.4.3-4ubuntu5
linux-firmware 1.34.7
linux-headers-2.6.32-37 2.6.32-37.81
linux-headers-2.6.32-37-generic 2.6.32-37.81
linux-headers-2.6.36-custom 2.6.36-custom-10.00.Custom
linux-headers-generic 2.6.32.37.43
linux-image-2.6.32-36-virtual 2.6.32-36.79
linux-image-2.6.36-custom 2.6.36-custom-10.00.Custom
linux-image-virtual 2.6.32.36.42
module-init-tools 3.11.1-2ubuntu1
systemtap 1.0-2
systemtap-runtime 1.0-2
udev 151-12.3
== egrep 'PROBE|TRACE|MARKER|_DEBUG_|MODULE' /lib/modules/2.6.36-custom/build/.config | grep -v not.set | sort | fmt -w 80 ==
CONFIG_AIC79XX_DEBUG_ENABLE=y CONFIG_AIC79XX_DEBUG_MASK=0
CONFIG_AIC7XXX_DEBUG_ENABLE=y CONFIG_AIC7XXX_DEBUG_MASK=0
CONFIG_ARCH_CPU_PROBE_RELEASE=y CONFIG_ARCH_MEMORY_PROBE=y
CONFIG_ARCH_SUPPORTS_DEBUG_PAGEALLOC=y CONFIG_BLK_DEV_IO_TRACE=y
CONFIG_CAN_PM_TRACE=y CONFIG_CAPI_TRACE=y CONFIG_CB710_DEBUG_ASSUMPTIONS=y
CONFIG_CONTEXT_SWITCH_TRACER=y CONFIG_DEBUG_BUGVERBOSE=y CONFIG_DEBUG_FS=y
CONFIG_DEBUG_INFO=y CONFIG_DEBUG_KERNEL=y CONFIG_DEBUG_MEMORY_INIT=y
CONFIG_DEBUG_RODATA=y CONFIG_DYNAMIC_FTRACE=y CONFIG_FTRACE_MCOUNT_RECORD=y
CONFIG_FTRACE_NMI_ENTER=y CONFIG_FTRACE=y CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_FUNCTION_TRACER=y CONFIG_GENERIC_IRQ_PROBE=y CONFIG_GENERIC_TRACER=y
CONFIG_HAVE_ARCH_TRACEHOOK=y CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y CONFIG_HAVE_FTRACE_NMI_ENTER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y CONFIG_HAVE_FUNCTION_TRACE_MCOUNT_TEST=y
CONFIG_HAVE_FUNCTION_TRACER=y CONFIG_HAVE_KPROBES=y CONFIG_HAVE_KRETPROBES=y
CONFIG_HAVE_MMIOTRACE_SUPPORT=y CONFIG_HAVE_OPTPROBES=y
CONFIG_HAVE_SYSCALL_TRACEPOINTS=y CONFIG_KPROBE_EVENT=y CONFIG_KPROBES=y
CONFIG_KRETPROBES=y CONFIG_MMIOTRACE=y CONFIG_MODULE_SRCVERSION_ALL=y
CONFIG_MODULES=y CONFIG_MODULE_UNLOAD=y CONFIG_MTD_DOCPROBE_ADDRESS=0
CONFIG_MTD_DOCPROBE=m CONFIG_MTD_GEN_PROBE=m CONFIG_MTD_JEDECPROBE=m
CONFIG_MTD_NAND_DISKONCHIP_PROBE_ADDRESS=0 CONFIG_MTD_QINFO_PROBE=m
CONFIG_NET_DCCPPROBE=m CONFIG_NETFILTER_XT_TARGET_TRACE=m CONFIG_NET_TCPPROBE=m
CONFIG_NOP_TRACER=y CONFIG_OCFS2_DEBUG_MASKLOG=y CONFIG_OPTPROBES=y
CONFIG_PM_TRACE_RTC=y CONFIG_PM_TRACE=y CONFIG_PNP_DEBUG_MESSAGES=y
CONFIG_SCSI_LPFC_DEBUG_FS=y CONFIG_STACKTRACE_SUPPORT=y
CONFIG_STACKTRACE=y CONFIG_TRACE_IRQFLAGS_SUPPORT=y CONFIG_TRACEPOINTS=y
CONFIG_USER_STACKTRACE_SUPPORT=y CONFIG_WIMAX_DEBUG_LEVEL=8
CONFIG_WIMAX_I2400M_DEBUG_LEVEL=8
== find /debugfs /proc /sys /dev -name '*kprobes*' 2>/dev/null | xargs grep . ==
/proc/sys/debug/kprobes-optimization:1
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Puzzling output of stp script
2011-12-24 19:14 ` Puzzling output of stp script contemplating zombie
2011-12-24 22:56 ` Adrien Kunysz
@ 2011-12-25 11:07 ` Josh Stone
2011-12-25 20:20 ` Adrien Kunysz
1 sibling, 1 reply; 6+ messages in thread
From: Josh Stone @ 2011-12-25 11:07 UTC (permalink / raw)
To: contemplating zombie; +Cc: systemtap
On 12/24/2011 10:31 AM, contemplating zombie wrote:
> Hi,
>
> I am new to systemtap and I was trying out following example script
> given in the documentation:
>
> probe kernel.function("*@net/socket.c") {
> printf ("%s -> %s\n", thread_indent(1), probefunc())
> }
>
> probe kernel.function("*@net/socket.c").return {
> printf ("%s <- %s\n", thread_indent(-1), probefunc())
> }
>
> I sshed into a remote machine and executed it. What I see is that the
> stack frames just keep on growing to right and do not return. Won't
> that cause a stack overflow eventually?
The reason is that you are probing more functions on entry than you are
on return. There's no stack issue; the probes are just imbalanced.
There are two flavors of entry probe: .call and .inline. If you don't
specify, then you get a union of both. However, .return probes only
work for the .call flavor, because there is no real return from inlined
functions.
So when you need balanced probes for entering and leaving functions, use
.call and .return. You could also be clever and represent the .inline
separately with thread_indent(0).
> 0 sshd(804): -> sock_poll
> 11 sshd(804): <- sock_poll
> 0 sshd(804): -> sock_aio_read
> 2 sshd(804): -> alloc_sock_iocb
> 3 sshd(804): <- alloc_sock_iocb
> 5 sshd(804): -> do_sock_read
> 7 sshd(804): -> __sock_recvmsg
> 9 sshd(804): -> __sock_recvmsg_nosec
> 15 sshd(804): <- sock_aio_read
Notice right here, you got a return from sock_aio_read, jumping back
over three other "calls". I'll bet that do_sock_read, __sock_recvmsg,
and __sock_recvmsg_nosec were all inlined in your kernel.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Puzzling output of stp script
2011-12-25 11:07 ` Josh Stone
@ 2011-12-25 20:20 ` Adrien Kunysz
2011-12-25 23:59 ` Mark Wielaard
0 siblings, 1 reply; 6+ messages in thread
From: Adrien Kunysz @ 2011-12-25 20:20 UTC (permalink / raw)
To: Josh Stone; +Cc: contemplating zombie, systemtap
[-- Attachment #1: Type: text/plain, Size: 2035 bytes --]
On Sat, Dec 24, 2011 at 09:55:55PM -0800, Josh Stone wrote:
> On 12/24/2011 10:31 AM, contemplating zombie wrote:
> > Hi,
> >
> > I am new to systemtap and I was trying out following example script
> > given in the documentation:
> >
> > probe kernel.function("*@net/socket.c") {
> > printf ("%s -> %s\n", thread_indent(1), probefunc())
> > }
> >
> > probe kernel.function("*@net/socket.c").return {
> > printf ("%s <- %s\n", thread_indent(-1), probefunc())
> > }
> >
> > I sshed into a remote machine and executed it. What I see is that the
> > stack frames just keep on growing to right and do not return. Won't
> > that cause a stack overflow eventually?
>
> The reason is that you are probing more functions on entry than you are
> on return. There's no stack issue; the probes are just imbalanced.
>
> There are two flavors of entry probe: .call and .inline. If you don't
> specify, then you get a union of both. However, .return probes only
> work for the .call flavor, because there is no real return from inlined
> functions.
>
> So when you need balanced probes for entering and leaving functions, use
> .call and .return. You could also be clever and represent the .inline
> separately with thread_indent(0).
And that particular example was already fixed a while ago btw:
http://sourceware.org/git/gitweb.cgi?p=systemtap.git;a=commitdiff;h=396afcee5ada2d207b7a6691d4b7ce473e7b2a65
> > 0 sshd(804): -> sock_poll
> > 11 sshd(804): <- sock_poll
> > 0 sshd(804): -> sock_aio_read
> > 2 sshd(804): -> alloc_sock_iocb
> > 3 sshd(804): <- alloc_sock_iocb
> > 5 sshd(804): -> do_sock_read
> > 7 sshd(804): -> __sock_recvmsg
> > 9 sshd(804): -> __sock_recvmsg_nosec
> > 15 sshd(804): <- sock_aio_read
>
> Notice right here, you got a return from sock_aio_read, jumping back
> over three other "calls". I'll bet that do_sock_read, __sock_recvmsg,
> and __sock_recvmsg_nosec were all inlined in your kernel.
[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: Puzzling output of stp script
2011-12-25 20:20 ` Adrien Kunysz
@ 2011-12-25 23:59 ` Mark Wielaard
0 siblings, 0 replies; 6+ messages in thread
From: Mark Wielaard @ 2011-12-25 23:59 UTC (permalink / raw)
To: Adrien Kunysz; +Cc: Josh Stone, contemplating zombie, systemtap
On Sun, Dec 25, 2011 at 11:09:52AM +0000, Adrien Kunysz wrote:
> And that particular example was already fixed a while ago btw:
> http://sourceware.org/git/gitweb.cgi?p=systemtap.git;a=commitdiff;h=396afcee5ada2d207b7a6691d4b7ce473e7b2a65
But it was still used in at least two places, the tutorial and beginner's
guide, without the .call modifier. Fixed those too and added Josh's
suggestion as an exercise:
commit 2e96e9163d84fe9772def0318216a6d6da1332a2
Author: Mark Wielaard <mjw@redhat.com>
Date: Sun Dec 25 20:56:53 2011 +0100
Use function.call and function.return in all thread_indent() examples.
If the .call modifier isn't used the function probes will match both .call
and .inline, but .return doesn't match any inlined functions leading to
unbalanced thread_indent output.
Cheers,
Mark
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2011-12-25 20:20 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <CAO_gTC6yXVN-6a-aj6YFy4Z_7wGaMRzbHTWWWdQOyWgD=g0rOQ@mail.gmail.com>
2011-12-24 19:14 ` Puzzling output of stp script contemplating zombie
2011-12-24 22:56 ` Adrien Kunysz
2011-12-25 5:56 ` contemplating zombie
2011-12-25 11:07 ` Josh Stone
2011-12-25 20:20 ` Adrien Kunysz
2011-12-25 23:59 ` Mark Wielaard
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).