This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: Puzzling output of stp script


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: signature.asc
Description: Digital signature


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]