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]

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


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


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