Puzzling output of stp script
Adrien Kunysz
adrien@kunysz.be
Sat Dec 24 22:56:00 GMT 2011
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:~#
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: Digital signature
URL: <http://sourceware.org/pipermail/systemtap/attachments/20111224/b54ed3f9/attachment.sig>
More information about the Systemtap
mailing list