* 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).