Re: Measure the Accept Queueing Time

["Benjamin" <benchu@tamu.edu>]

 Oh! Thank you very much and sorry to take you so much time!
Now, I am trying to implement what you said. It seems not easy to me!^_^
Thanks again!
 Benjamin Chu
----- Original Message ----- 
From: "Frank Ch. Eigler" <fche@redhat.com>
To: "Benjamin Chu" <benchu@tamu.edu>
Cc: <linux-kernel@vger.kernel.org>; <systemtap@sources.redhat.com>
Sent: Friday, February 03, 2006 6:13 PM
Subject: Re: Measure the Accept Queueing Time


>
> Benjamin Chu <benchu@tamu.edu> writes:
>
> > [...]  All I want is to measure the amount of time when a open
> > request is in the accept queue. [...]
> > p.s. My Linux Kernel Version is 2.4.25
>
> Dude, you made me spend several hours playing with systemtap to solve
> this simple-sounding problem.  :-)
>
> At the end, I have a script (attached below) that works on one
> particular kernel build (a beta RHEL4 kernel, which has the systemtap
> prerequisite kprobes, but uses the same networking structure).
> Unfortunately, it also demonstrated some of the work we have to do in
> systemtap land to make it work better.
>
> The good news: here is the output of the script running on a vmware
> instance that has only single socket listener program, being briefly
> tickled by hand, then hammered by "nc" connections in a loop.  The
> lines came out every ten seconds (as requested by the script, see
> below), and report on the number of successful accept()s, plus the
> number of microseconds that each open_request* was in the
> accept_queue.
>
> % socket -l -s NNNN &
> [1] 25384
> % stap -g acceptdelay.stp
> [1139011591] socket(25384) count=1 avg=1487us
> [1139011601] socket(25384) count=9 avg=560us
> [1139011611] socket(25384) count=6 avg=915us
> [1139011621] socket(25384) count=747 avg=604us
> [1139011631] socket(25384) count=1280 avg=558us
> [1139011641] socket(25384) count=1147 avg=547us
> [1139011645] socket(25384) count=25 avg=471us
>
> Is that the sort of data you were hoping to see?
>
> The systemtap translator unfortunately has problems identifying the
> most ideal probe insertion points, based on source code coordinates or
> function names.  The interception of inline functions is weak.  At the
> present, we also don't have/use the benefit of hooks inserted into the
> kernel just for us, which would make probes simple and precise.  But
> all these problems are being worked on.
>
> So, as a stop-gap for this warts-and-all demonstration, the script
> just uses hard-coded PC addresses.  Please look beyond that and use
> your imagination!
>
> - FChE
>
>
> #! stap -g
>
> # This embedded-C function is needed to extract a tcp_opt field
> # from a pointer cast to generic struct sock*.  Later, systemtap
> # will offer first class syntax and protected operation for this.
> %{
> #include <net/tcp.h>
> %}
> function tcp_aq_head:long (sock:long)
> %{
>   struct tcp_opt *tp = tcp_sk ((struct sock*) (uintptr_t) THIS->sock);
>   THIS->__retvalue = (int64_t) (uintptr_t) tp->accept_queue;
> %}
>
>
> global open_request_arrivals # indexed by open_request pointer
> global open_request_delays # stats, indexed by pid and execname
>
> probe # a spot in the open_request creation path
> # XXX: the following commented-out probe points should also work
> # kernel.inline("tcp_acceptq_queue")
> # kernel.function("tcp_v4_conn_request")
> # kernel.inline("tcp_openreq_init")
>   kernel.statement("*@net/ipv4/tcp_ipv4.c:1472") # after
tcp_openreq_init()
> {
>   open_request_arrivals[$req] = gettimeofday_us()
> }
>
>
> # One could also probe at entry of tcp_accept itself, to track
> # whether an accept() syscall was blocked by absence of pending
> # open_requests.
>
>
> probe # a spot in tcp_accept, after pending open_request found
> # kernel.statement("*@net/ipv4/tcp_ipv4.c:1922")
>   kernel.statement (0xc029eec8) # near req = tp->accept_queue
> {
>   req = tcp_aq_head ($sk) # tcp_sk(sk)->accept_queue; $req should work too
>   then = open_request_arrivals[req]
>   if (then) {
>     delete open_request_arrivals[req] # save memory
>     now = gettimeofday_us()
>     open_request_delays[pid(),execname()] <<< now-then
>   }
> }
>
>
> probe timer.ms(10000), end # periodically and at session shutdown
> {
>   now=gettimeofday_s()
>   foreach ([pid+,execname] in open_request_delays) # sort by pid
>     printf("[%d] %s(%d) count=%d avg=%dus\n", now, execname, pid,
>            @count(open_request_delays[pid,execname]),
>            @avg(open_request_delays[pid,execname]))
>   delete open_request_delays
> }
>
>
> # Some preprocessor magic to prevent someone from running this
> # demonstration script (with its hard-coded probe addresses)
> # on another kernel build
> %( kernel_vr == "2.6.9-30.ELsmp" %? %( arch == "i686" %? /* OK */
>                                                       %: BADARCH %)
>                                  %: BADVERSION %)
>