From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 29639 invoked by alias); 24 Dec 2011 19:14:53 -0000 Received: (qmail 29629 invoked by uid 22791); 24 Dec 2011 19:14:50 -0000 X-SWARE-Spam-Status: No, hits=-1.6 required=5.0 tests=AWL,BAYES_00,TW_CV X-Spam-Check-By: sourceware.org Received: from xvm-20-226.ghst.net (HELO fruli.krunch.be) (92.243.20.226) by sourceware.org (qpsmtpd/0.43rc1) with ESMTP; Sat, 24 Dec 2011 19:14:33 +0000 Received: from localhost (localhost [127.0.0.1]) by fruli.krunch.be (Postfix) with ESMTP id A8D42228A7; Sat, 24 Dec 2011 19:11:51 +0000 (UTC) Date: Sat, 24 Dec 2011 22:56:00 -0000 From: Adrien Kunysz To: contemplating zombie Cc: systemtap@sourceware.org Subject: Re: Puzzling output of stp script Message-ID: <20111224191702.GA17069@chouffe> References: MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha1; protocol="application/pgp-signature"; boundary="nFreZHaLTZJo0R7j" Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.20 (2009-06-14) X-IsSubscribed: yes Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org X-SW-Source: 2011-q4/txt/msg00422.txt.bz2 --nFreZHaLTZJo0R7j Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: quoted-printable Content-length: 18648 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: >=20 > probe kernel.function("*@net/socket.c") { > =A0 =A0 =A0 printf ("%s -> %s\n", thread_indent(1), probefunc()) > } >=20 > probe kernel.function("*@net/socket.c").return { > =A0 =A0 =A0 printf ("%s <- %s\n", thread_indent(-1), probefunc()) > } >=20 > 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: >=20 > root@ubuntu:~# touch t.stp > root@ubuntu:~# emacs -nw t.stp > root@ubuntu:~# stap t.stp >=20 > 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 >=20 > 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 >=20 > 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_io= cb > 2362703 sshd(804): <- alloc_sock_io= cb > 2362707 sshd(804): -> do_sock_write > 2362711 sshd(804): -> __sock_sendm= sg > 2362757 sshd(804): <- sock_aio_wri= te > 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_wri= te > 2562538 sshd(804): -> alloc_sock_= iocb > 2562542 sshd(804): <- alloc_sock_= iocb > 2562547 sshd(804): -> do_sock_wri= te > 2562551 sshd(804): -> __sock_sen= dmsg > 2562595 sshd(804): <- sock_aio_w= rite > 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_w= rite > 2762654 sshd(804): -> alloc_soc= k_iocb > 2762658 sshd(804): <- alloc_soc= k_iocb > 2762663 sshd(804): -> do_sock_w= rite > 2762667 sshd(804): -> __sock_s= endmsg > 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_p= oll > 2962515 sshd(804): <- sock_p= oll > ^C3162600 sshd(804): -> sock= _poll > 3162615 sshd(804): <- sock_p= oll > 3162648 sshd(804): -> sock_p= oll > 3162653 sshd(804): <- sock_p= oll > 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:~# --nFreZHaLTZJo0R7j Content-Type: application/pgp-signature; name="signature.asc" Content-Description: Digital signature Content-Disposition: inline Content-length: 198 -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.10 (GNU/Linux) iEYEARECAAYFAk72JS4ACgkQKLX03ZSPZGwWewCgj5Uzz4nMlHeFNzzkK6cPdQCH q5YAn1EpCJ7TsC2f8iZumRg+LDzF/uW4 =9ChX -----END PGP SIGNATURE----- --nFreZHaLTZJo0R7j--