[RFC/PATCH] TCP and Unix socket accept queue time examples

[RFC/PATCH] TCP and Unix socket accept queue time examples

[Eric Wong]

These examples can be useful for measuring how long it
took an application to accept a newly-connected client.
---
 This is my first submission to SystemTap, comments greatly appreciated!

 .../network/tcp_acceptq_time.meta                  | 13 ++++++++
 .../network/tcp_acceptq_time.stp                   | 17 +++++++++++
 .../network/unix_acceptq_time.meta                 | 13 ++++++++
 .../network/unix_acceptq_time.stp                  | 35 ++++++++++++++++++++++
 4 files changed, 78 insertions(+)
 create mode 100644 testsuite/systemtap.examples/network/tcp_acceptq_time.meta
 create mode 100755 testsuite/systemtap.examples/network/tcp_acceptq_time.stp
 create mode 100644 testsuite/systemtap.examples/network/unix_acceptq_time.meta
 create mode 100755 testsuite/systemtap.examples/network/unix_acceptq_time.stp

diff --git a/testsuite/systemtap.examples/network/tcp_acceptq_time.meta b/testsuite/systemtap.examples/network/tcp_acceptq_time.meta
new file mode 100644
index 0000000..a2f5f81
--- /dev/null
+++ b/testsuite/systemtap.examples/network/tcp_acceptq_time.meta
@@ -0,0 +1,13 @@
+title: Accept Queue time for TCP sockets
+name: tcp_acceptq_time.stp
+version: 1.0
+author: Eric Wong
+keywords: network queue accept tcp
+subsystem: network
+status: experimental
+exit: user-controlled
+output: trace
+scope: system-wide
+description: Print out executable name, PID and time an accepted TCP socket spent in the listen queue
+test_check: stap -p4 tcp_acceptq_time.stp
+test_installcheck: stap tcp_acceptq_time.stp -c "sleep 0.2"
diff --git a/testsuite/systemtap.examples/network/tcp_acceptq_time.stp b/testsuite/systemtap.examples/network/tcp_acceptq_time.stp
new file mode 100755
index 0000000..b979804
--- /dev/null
+++ b/testsuite/systemtap.examples/network/tcp_acceptq_time.stp
@@ -0,0 +1,17 @@
+#! /usr/bin/env stap
+
+/* wrap-around just in case */
+global tcp_acceptq_start%
+
+probe kernel.function("sk_acceptq_added") {
+	tcp_acceptq_start[$sk] = cpu_clock_us(0)
+}
+
+probe kernel.function("sk_acceptq_removed") {
+	started = tcp_acceptq_start[$sk]
+	if (started) {
+		delete tcp_acceptq_start[$sk]
+		diff = cpu_clock_us(0) - started
+		printf("%s[%d] %ld\n", execname(), pid(), diff)
+	}
+}
diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.meta b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
new file mode 100644
index 0000000..7ed5c88
--- /dev/null
+++ b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
@@ -0,0 +1,13 @@
+title: Accept Queue time for Unix stream sockets
+name: unix_acceptq_time.stp
+version: 1.0
+author: Eric Wong
+keywords: network queue accept unix listen
+subsystem: network
+status: experimental
+exit: user-controlled
+output: trace
+scope: system-wide
+description: Print out executable name, PID and time an accepted Unix socket spent in the listen queue
+test_check: stap -p4 unix_acceptq_time.stp
+test_installcheck: stap unix_acceptq_time.stp -c "sleep 0.2"
diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.stp b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
new file mode 100755
index 0000000..e514d6d
--- /dev/null
+++ b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
@@ -0,0 +1,35 @@
+#! /usr/bin/env stap
+
+/* wrap-around just in case there are more unix_create1() callers */
+global unix_acceptq_start%
+
+/*
+ * Linux 3.6.x only has two unix_create1() callers:
+ * - unix_stream_connect() - we care about this
+ * - unix_create()         - we do not care about this
+ */
+probe kernel.function("unix_create1").return {
+	unix_acceptq_start[$return] = cpu_clock_us(0)
+}
+
+/*
+ * we only care about unix_create1() called from unix_stream_connect(),
+ * so avoid wasting space here.
+ * Maybe future (or past) kernels had more unix_create1() callers,
+ * wraparound for the unix_acceptq_start array will prevent us from hitting limits
+ */
+probe kernel.function("unix_create").return {
+	delete unix_acceptq_start[$return]
+}
+
+probe kernel.function("unix_accept").return {
+	if ($return != 0)
+		next
+	sk = @cast($newsock, "struct socket")->sk
+	started = unix_acceptq_start[sk]
+	if (started) {
+		delete unix_acceptq_start[sk]
+		diff = cpu_clock_us(0) - started
+		printf("%s[%d] %ld\n", execname(), pid(), diff)
+	}
+}
-- 
Eric Wong

Re: [RFC/PATCH] TCP and Unix socket accept queue time examples

[Eric Wong]

Eric Wong <normalperson@yhbt.net> wrote:
> These examples can be useful for measuring how long it
> took an application to accept a newly-connected client.
> ---
>  This is my first submission to SystemTap, comments greatly appreciated!

ping?

Re: [RFC/PATCH] TCP and Unix socket accept queue time examples

[William Cohen]

On 12/07/2012 08:13 PM, Eric Wong wrote:
> These examples can be useful for measuring how long it
> took an application to accept a newly-connected client.
> ---
>  This is my first submission to SystemTap, comments greatly appreciated!
> 
>  .../network/tcp_acceptq_time.meta                  | 13 ++++++++
>  .../network/tcp_acceptq_time.stp                   | 17 +++++++++++
>  .../network/unix_acceptq_time.meta                 | 13 ++++++++
>  .../network/unix_acceptq_time.stp                  | 35 ++++++++++++++++++++++
>  4 files changed, 78 insertions(+)
>  create mode 100644 testsuite/systemtap.examples/network/tcp_acceptq_time.meta
>  create mode 100755 testsuite/systemtap.examples/network/tcp_acceptq_time.stp
>  create mode 100644 testsuite/systemtap.examples/network/unix_acceptq_time.meta
>  create mode 100755 testsuite/systemtap.examples/network/unix_acceptq_time.stp
> 
> diff --git a/testsuite/systemtap.examples/network/tcp_acceptq_time.meta b/testsuite/systemtap.examples/network/tcp_acceptq_time.meta
> new file mode 100644
> index 0000000..a2f5f81
> --- /dev/null
> +++ b/testsuite/systemtap.examples/network/tcp_acceptq_time.meta
> @@ -0,0 +1,13 @@
> +title: Accept Queue time for TCP sockets
> +name: tcp_acceptq_time.stp
> +version: 1.0
> +author: Eric Wong
> +keywords: network queue accept tcp
> +subsystem: network
> +status: experimental
> +exit: user-controlled
> +output: trace
> +scope: system-wide
> +description: Print out executable name, PID and time an accepted TCP socket spent in the listen queue
> +test_check: stap -p4 tcp_acceptq_time.stp
> +test_installcheck: stap tcp_acceptq_time.stp -c "sleep 0.2"
> diff --git a/testsuite/systemtap.examples/network/tcp_acceptq_time.stp b/testsuite/systemtap.examples/network/tcp_acceptq_time.stp
> new file mode 100755
> index 0000000..b979804
> --- /dev/null
> +++ b/testsuite/systemtap.examples/network/tcp_acceptq_time.stp
> @@ -0,0 +1,17 @@
> +#! /usr/bin/env stap
> +
> +/* wrap-around just in case */

what does the comment above mean?

> +global tcp_acceptq_start%

What is the '%' doing at the end of tcp_acceptq_start?

> +
> +probe kernel.function("sk_acceptq_added") {
> +	tcp_acceptq_start[$sk] = cpu_clock_us(0)
> +}

Why use cpu_clock_us(0) from processor 0? On multiprocessor systems this can cause an interprocessor interrupt.
Why not use gettimeofday_us() instead?

> +
> +probe kernel.function("sk_acceptq_removed") {
> +	started = tcp_acceptq_start[$sk]
> +	if (started) {
> +		delete tcp_acceptq_start[$sk]
> +		diff = cpu_clock_us(0) - started
> +		printf("%s[%d] %ld\n", execname(), pid(), diff)
> +	}
> +}

The sk_acceptq_added increments backlog and sk_accepts_removed decrements, so there could be more than thing listening.  So this is only going to count the time from the last sk_acceptq_added to the first sk_acceptq_removed.  Also it sk_acceptq_remove isn't clearing out tcp_acceptq_start global array so eventually that will fill up. Which tiome is most useful:

-from earliest sk_acceptq_added to earliest sk_acceptq_removed
-from latest sk_acceptq_added to earliest sk_acceptq_removed
-from earliest sk_acceptq_added to latest sk_acceptq_removed
-from latest sk_acceptq_added to latest sk_acceptq_removed

> diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.meta b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
> new file mode 100644
> index 0000000..7ed5c88
> --- /dev/null
> +++ b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
> @@ -0,0 +1,13 @@
> +title: Accept Queue time for Unix stream sockets
> +name: unix_acceptq_time.stp
> +version: 1.0
> +author: Eric Wong
> +keywords: network queue accept unix listen
> +subsystem: network
> +status: experimental
> +exit: user-controlled
> +output: trace
> +scope: system-wide
> +description: Print out executable name, PID and time an accepted Unix socket spent in the listen queue
> +test_check: stap -p4 unix_acceptq_time.stp
> +test_installcheck: stap unix_acceptq_time.stp -c "sleep 0.2"
> diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.stp b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
> new file mode 100755
> index 0000000..e514d6d
> --- /dev/null
> +++ b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
> @@ -0,0 +1,35 @@
> +#! /usr/bin/env stap
> +
> +/* wrap-around just in case there are more unix_create1() callers */
> +global unix_acceptq_start%

What is the '%' at the end of the line for?

> +
> +/*
> + * Linux 3.6.x only has two unix_create1() callers:
> + * - unix_stream_connect() - we care about this
> + * - unix_create()         - we do not care about this
> + */
> +probe kernel.function("unix_create1").return {
> +	unix_acceptq_start[$return] = cpu_clock_us(0)
> +}

unix_create1() is a static function in the kernel that appears to only be called by other functions in the file.  This currently works, but this function could be inlined by the compiler and then the function().return probe point won't be available.

Probably should use gettimeofday_us() rather than the cpu_clock_us(0) which could cause an interprocessor interrupt on smp machines.
> +
> +/*
> + * we only care about unix_create1() called from unix_stream_connect(),
> + * so avoid wasting space here.
> + * Maybe future (or past) kernels had more unix_create1() callers,
> + * wraparound for the unix_acceptq_start array will prevent us from hitting limits
> + */
> +probe kernel.function("unix_create").return {
> +	delete unix_acceptq_start[$return]
> +}

Would it be possible to watch the unix_stream_connect() directly and avoid probing unix_create() and unix_create1()?


> +
> +probe kernel.function("unix_accept").return {
> +	if ($return != 0)
> +		next
> +	sk = @cast($newsock, "struct socket")->sk
> +	started = unix_acceptq_start[sk]
> +	if (started) {
> +		delete unix_acceptq_start[sk]
> +		diff = cpu_clock_us(0) - started
> +		printf("%s[%d] %ld\n", execname(), pid(), diff)
> +	}
> +}
> 

-Will

Re: [RFC/PATCH] TCP and Unix socket accept queue time examples

[Eric Wong]

William Cohen <wcohen@redhat.com> wrote:
> On 12/07/2012 08:13 PM, Eric Wong wrote:
> > +++ b/testsuite/systemtap.examples/network/tcp_acceptq_time.stp
> > @@ -0,0 +1,17 @@
> > +#! /usr/bin/env stap
> > +
> > +/* wrap-around just in case */
> 
> what does the comment above mean?
> 
> > +global tcp_acceptq_start%
> 
> What is the '%' doing at the end of tcp_acceptq_start?

That makes the array wrap-around when it hits MAPMAXENTRIES
(in case I have bugs or the kernel changes).  Perhaps it ends up
hiding bugs and its a bad idea...

> > +
> > +probe kernel.function("sk_acceptq_added") {
> > +	tcp_acceptq_start[$sk] = cpu_clock_us(0)
> > +}
> 
> Why use cpu_clock_us(0) from processor 0? On multiprocessor systems this can cause an interprocessor interrupt.
> Why not use gettimeofday_us() instead?

I wanted a monotonic clock in case system time changed during
measurement.  I stuck to using processor 0 because the documentation
stated there could be drift between CPUs.

gettimeofday_* is probably fine as most production systems have fairly
stable time and some users are stuck on older, distro-provided versions
of SystemTap without the newish cpu_clock_* functions.

> > +probe kernel.function("sk_acceptq_removed") {
> > +	started = tcp_acceptq_start[$sk]
> > +	if (started) {
> > +		delete tcp_acceptq_start[$sk]
> > +		diff = cpu_clock_us(0) - started
> > +		printf("%s[%d] %ld\n", execname(), pid(), diff)
> > +	}
> > +}
> 
> The sk_acceptq_added increments backlog and sk_accepts_removed decrements, so there could be more than thing listening.  So this is only going to count the time from the last sk_acceptq_added to the first sk_acceptq_removed.  Also it sk_acceptq_remove isn't clearing out tcp_acceptq_start global array so eventually that will fill up. Which tiome is most useful:
> 
> -from earliest sk_acceptq_added to earliest sk_acceptq_removed
> -from latest sk_acceptq_added to earliest sk_acceptq_removed
> -from earliest sk_acceptq_added to latest sk_acceptq_removed
> -from latest sk_acceptq_added to latest sk_acceptq_removed

Good catch!  I based that code off hints I got from fche earlier:
http://mid.gmane.org/y0m38zrro7u.fsf@fche.csb

Since I want to measure the time of every single accepted socket,
I should probably look into reqsk_queue_* functions instead and
ignore the sk_acceptq_* functions.

> > diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.meta b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
> > @@ -0,0 +1,35 @@
> > +#! /usr/bin/env stap
> > +
> > +/* wrap-around just in case there are more unix_create1() callers */
> > +global unix_acceptq_start%
> 
> What is the '%' at the end of the line for?

Same reasoning as the TCP one above.

> > +
> > +/*
> > + * Linux 3.6.x only has two unix_create1() callers:
> > + * - unix_stream_connect() - we care about this
> > + * - unix_create()         - we do not care about this
> > + */
> > +probe kernel.function("unix_create1").return {
> > +	unix_acceptq_start[$return] = cpu_clock_us(0)
> > +}
> 
> unix_create1() is a static function in the kernel that appears to only be called by other functions in the file.  This currently works, but this function could be inlined by the compiler and then the function().return probe point won't be available.

Ah, OK.  See below...

> Probably should use gettimeofday_us() rather than the cpu_clock_us(0) which could cause an interprocessor interrupt on smp machines.
> > +
> > +/*
> > + * we only care about unix_create1() called from unix_stream_connect(),
> > + * so avoid wasting space here.
> > + * Maybe future (or past) kernels had more unix_create1() callers,
> > + * wraparound for the unix_acceptq_start array will prevent us from hitting limits
> > + */
> > +probe kernel.function("unix_create").return {
> > +	delete unix_acceptq_start[$return]
> > +}
> 
> Would it be possible to watch the unix_stream_connect() directly and avoid probing unix_create() and unix_create1()?

I tried probing unix_stream_connect() at first, but was unable to figure
out how to get the newsk variable, so I fell back to probing
unix_create1().

I haven't looked harder, yet, but if anybody has suggestions or hints I'd
like to hear them :)

I think my original (unpublished) version of this probed
__skb_queue_tail, even.

Thank you very much for the comments, I'll start working on an updated
patch.

[RFC/PATCH v2] INET and Unix socket accept queue time examples

[Eric Wong]

Eric Wong <normalperson@yhbt.net> wrote:
> Thank you very much for the comments, I'll start working on an updated
> patch.

Here's an updated version below.
Changes since the first:

* Using gettimeofday_us() instead of cpu_clock_us(0), since that
  seems to be favored in existing examples and be more performant.

* renamed TCP->INET, since it's easier to just probe all INET
  sockets instead of just TCP (and users will likely only care
  about the most-heavily used socket family on the system).

* INET now accurately measures per-client queue times, the
  previous version based on sk_acceptq_* functions was incorrect
  as pointed out by William Cohen.

-------------------------------- 8< ------------------------------
From 90504d81aec0a92e3832770f331158ef070ed356 Mon Sep 17 00:00:00 2001
From: Eric Wong <normalperson@yhbt.net>
Date: Sat, 8 Dec 2012 00:54:24 +0000
Subject: [PATCH] INET and Unix socket accept queue time examples

These examples can be useful for measuring how long it
takes an application to accept() a newly-connected client.
---
 .../network/inet_acceptq_time.meta                 | 13 ++++++++
 .../network/inet_acceptq_time.stp                  | 17 ++++++++++
 .../network/unix_acceptq_time.meta                 | 13 ++++++++
 .../network/unix_acceptq_time.stp                  | 36 ++++++++++++++++++++++
 4 files changed, 79 insertions(+)
 create mode 100644 testsuite/systemtap.examples/network/inet_acceptq_time.meta
 create mode 100755 testsuite/systemtap.examples/network/inet_acceptq_time.stp
 create mode 100644 testsuite/systemtap.examples/network/unix_acceptq_time.meta
 create mode 100755 testsuite/systemtap.examples/network/unix_acceptq_time.stp

diff --git a/testsuite/systemtap.examples/network/inet_acceptq_time.meta b/testsuite/systemtap.examples/network/inet_acceptq_time.meta
new file mode 100644
index 0000000..fa07d75
--- /dev/null
+++ b/testsuite/systemtap.examples/network/inet_acceptq_time.meta
@@ -0,0 +1,13 @@
+title: Accept Queue time for INET sockets
+name: inet_acceptq_time.stp
+version: 1.0
+author: Eric Wong
+keywords: network queue accept inet
+subsystem: network
+status: experimental
+exit: user-controlled
+output: trace
+scope: system-wide
+description: Print out executable name, PID and time an accepted INET socket spent in the listen queue
+test_check: stap -p4 inet_acceptq_time.stp
+test_installcheck: stap inet_acceptq_time.stp -c "sleep 0.2"
diff --git a/testsuite/systemtap.examples/network/inet_acceptq_time.stp b/testsuite/systemtap.examples/network/inet_acceptq_time.stp
new file mode 100755
index 0000000..7fffe31
--- /dev/null
+++ b/testsuite/systemtap.examples/network/inet_acceptq_time.stp
@@ -0,0 +1,17 @@
+#! /usr/bin/env stap
+
+/* wrap-around just in case more inet_csk_accept-like functions come along */
+global inet_acceptq_start%
+
+probe kernel.function("inet_csk_reqsk_queue_add") {
+	inet_acceptq_start[$child] = gettimeofday_us()
+}
+
+probe kernel.function("inet_csk_accept").return {
+	started = inet_acceptq_start[$return]
+	delete inet_acceptq_start[$return]
+	if (started) {
+		diff = gettimeofday_us() - started
+		printf("%s[%d] %ld\n", execname(), pid(), diff)
+	}
+}
diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.meta b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
new file mode 100644
index 0000000..7ed5c88
--- /dev/null
+++ b/testsuite/systemtap.examples/network/unix_acceptq_time.meta
@@ -0,0 +1,13 @@
+title: Accept Queue time for Unix stream sockets
+name: unix_acceptq_time.stp
+version: 1.0
+author: Eric Wong
+keywords: network queue accept unix listen
+subsystem: network
+status: experimental
+exit: user-controlled
+output: trace
+scope: system-wide
+description: Print out executable name, PID and time an accepted Unix socket spent in the listen queue
+test_check: stap -p4 unix_acceptq_time.stp
+test_installcheck: stap unix_acceptq_time.stp -c "sleep 0.2"
diff --git a/testsuite/systemtap.examples/network/unix_acceptq_time.stp b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
new file mode 100755
index 0000000..31ed4b1
--- /dev/null
+++ b/testsuite/systemtap.examples/network/unix_acceptq_time.stp
@@ -0,0 +1,36 @@
+#! /usr/bin/env stap
+
+/* wrap-around just in case there are more unix_create1() callers */
+global unix_acceptq_start%
+
+/*
+ * Linux 3.6.x only has two unix_create1() callers:
+ * - unix_stream_connect() - we care about this
+ * - unix_create()         - we do not care about this
+ */
+probe kernel.function("unix_create1").return {
+	unix_acceptq_start[$return] = gettimeofday_us()
+}
+
+/*
+ * we only care about unix_create1() called from unix_stream_connect(),
+ * so avoid wasting space here.
+ * Maybe future (or past) kernels had more unix_create1() callers,
+ * wraparound for the unix_acceptq_start array will prevent us from
+ * hitting limits
+ */
+probe kernel.function("unix_create").return {
+	delete unix_acceptq_start[$return]
+}
+
+probe kernel.function("unix_accept").return {
+	if ($return != 0)
+		next
+	sk = @cast($newsock, "struct socket")->sk
+	started = unix_acceptq_start[sk]
+	delete unix_acceptq_start[sk]
+	if (started) {
+		diff = gettimeofday_us() - started
+		printf("%s[%d] %ld\n", execname(), pid(), diff)
+	}
+}
-- 
Eric Wong