preliminary systemtap support for tracing

We will key most client events by pid() and file descriptors,
as this is least ambiguous.  There are some minor refactorings
to pass "struct mog_fd *" around as much as possible instead of
"struct mog_http *".

14 files changed, 221 insertions, 33 deletions

diff --git a/.gitignore b/.gitignore
index 04e3afe..925e468 100644
--- a/.gitignore
+++ b/.gitignore
@@ -29,6 +29,7 @@
 /listen_parser.c
 /mgmt_parser.c
 /valid_put_path.c
+probes.h
 /stamp-h1
 /tmp
 /valid_path.c
diff --git a/Makefile.am b/Makefile.am
index 3ce8cf0..157242f 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -87,6 +87,7 @@ mog_src += sig.c
 mog_src += svc.c
 mog_src += svc_dev.c
 mog_src += thrpool.c
+mog_src += trace.h
 mog_src += trywrite.c
 mog_src += util.h
 mog_src += upgrade.c
@@ -113,7 +114,7 @@ chunk_parser.c: chunk_parser.rl http_common.rl
 
 BUILT_SOURCES = $(top_srcdir)/.version
 bin_PROGRAMS = cmogstored
-cmogstored_SOURCES = $(mog_src) $(RL_CGEN) cmogstored.c
+cmogstored_SOURCES = $(mog_src) $(RL_CGEN) cmogstored.c probes.d
 
 RUBY = ruby
 PERL = perl
@@ -217,3 +218,14 @@ $(top_srcdir)/.version:
         echo $(VERSION) > $@-t && mv $@-t $@
 dist-hook:
         echo $(VERSION) > $(distdir)/.tarball-version
+
+if ENABLE_SYSTEMTAP
+BUILT_SOURCES += probes.h
+probes.h: probes.d
+        $(DTRACE) -C -h -s $< -o $@
+
+probes.o: probes.d
+        $(DTRACE) -C -G -s $< -o $@
+
+LDADD += probes.o
+endif
diff --git a/cmogstored.h b/cmogstored.h
index 3a7812d..62e9136 100644
--- a/cmogstored.h
+++ b/cmogstored.h
@@ -440,7 +440,7 @@ void mog_http_init(struct mog_http *, struct mog_svc *);
 enum mog_parser_state mog_http_parse(struct mog_http *, char *buf, size_t len);
 
 /* http_get.c */
-void mog_http_get_open(struct mog_http *, char *buf);
+void mog_http_get_open(struct mog_fd *, char *buf);
 enum mog_next mog_http_get_in_progress(struct mog_fd *);
 
 /* http.c */
@@ -454,11 +454,11 @@ char *mog_http_path(struct mog_http *, char *buf);
 void mog_http_reset(struct mog_http *);
 
 /* http_dav.c */
-void mog_http_delete(struct mog_http *http, char *buf);
-void mog_http_mkcol(struct mog_http *http, char *buf);
+void mog_http_delete(struct mog_fd *, char *buf);
+void mog_http_mkcol(struct mog_fd *, char *buf);
 
 /* http_put.c */
-void mog_http_put(struct mog_http *http, char *buf, size_t buf_len);
+void mog_http_put(struct mog_fd *, char *buf, size_t buf_len);
 enum mog_next mog_http_put_in_progress(struct mog_fd *);
 bool mog_http_write_full(struct mog_fd *file_mfd, char *buf, size_t buf_len);
 
diff --git a/configure.ac b/configure.ac
index adb37f3..8a9e6d1 100644
--- a/configure.ac
+++ b/configure.ac
@@ -61,5 +61,7 @@ case $build_os in
 esac
 ])
 
+CM_SYSTEMTAP
+
 AC_CONFIG_FILES([Makefile lib/Makefile])
 AC_OUTPUT
diff --git a/http.c b/http.c
index f2a66e0..5fa34bc 100644
--- a/http.c
+++ b/http.c
@@ -3,6 +3,7 @@
  * License: GPLv3 or later (see COPYING for details)
  */
 #include "cmogstored.h"
+#include "trace.h"
 #include "http.h"
 
 /*
@@ -59,15 +60,17 @@ http_defer_rbuf(struct mog_http *http, struct mog_rbuf *rbuf, size_t buf_len)
 }
 
 static void
-http_process_client(struct mog_http *http, char *buf, size_t buf_len)
+http_process_client(struct mog_fd *mfd, char *buf, size_t buf_len)
 {
+        struct mog_http *http = &mfd->as.http;
+
         switch (http->_p.http_method) {
         case MOG_HTTP_METHOD_NONE: assert(0 && "BUG: unset HTTP method");
-        case MOG_HTTP_METHOD_GET: mog_http_get_open(http, buf); break;
-        case MOG_HTTP_METHOD_HEAD: mog_http_get_open(http, buf); break;
-        case MOG_HTTP_METHOD_DELETE: mog_http_delete(http, buf); break;
-        case MOG_HTTP_METHOD_MKCOL: mog_http_mkcol(http, buf); break;
-        case MOG_HTTP_METHOD_PUT: mog_http_put(http, buf, buf_len); break;
+        case MOG_HTTP_METHOD_GET: mog_http_get_open(mfd, buf); break;
+        case MOG_HTTP_METHOD_HEAD: mog_http_get_open(mfd, buf); break;
+        case MOG_HTTP_METHOD_DELETE: mog_http_delete(mfd, buf); break;
+        case MOG_HTTP_METHOD_MKCOL: mog_http_mkcol(mfd, buf); break;
+        case MOG_HTTP_METHOD_PUT: mog_http_put(mfd, buf, buf_len); break;
         }
 }
 
@@ -158,6 +161,9 @@ static enum mog_next http_queue_step(struct mog_fd *mfd)
 reread:
         r = read(mfd->fd, buf + off, rbuf->rcapa - off);
         if (r > 0) {
+                if (off == 0)
+                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(false));
+
                 buf_len = r + off;
 parse:
                 state = mog_http_parse(http, buf, buf_len);
@@ -178,7 +184,7 @@ parse:
                         off = http->_p.offset;
                         goto reread;
                 case MOG_PARSER_DONE:
-                        http_process_client(http, buf, buf_len);
+                        http_process_client(mfd, buf, buf_len);
                         if (http->wbuf == MOG_WR_ERROR)
                                 return MOG_NEXT_CLOSE;
                         if (http->wbuf) {
@@ -190,12 +196,17 @@ parse:
                         } else if (!http->_p.persistent) {
                                 return MOG_NEXT_CLOSE;
                         } else {
+                                /* pipelined request */
+                                if (buf_len)
+                                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(true));
+
                                 http_defer_rbuf(http, rbuf, buf_len);
                                 mog_http_reset(http);
                         }
                         return MOG_NEXT_ACTIVE;
                 }
         } else if (r == 0) { /* client shut down */
+                TRACE(CMOGSTORED_HTTP_RDCLOSE(buf_len));
                 return MOG_NEXT_CLOSE;
         } else {
                 switch (errno) {
@@ -209,8 +220,11 @@ parse:
                 case EINTR: goto reread;
                 case ECONNRESET:
                 case ENOTCONN:
+                        /* these errors are too common to log, normally */
+                        TRACE(CMOGSTORED_HTTP_RDERR(buf_len, errno));
                         return MOG_NEXT_CLOSE;
                 default:
+                        TRACE(CMOGSTORED_HTTP_RDERR(buf_len, errno));
                         syslog(LOG_NOTICE, "http client died: %m");
                         return MOG_NEXT_CLOSE;
                 }
@@ -264,28 +278,48 @@ void mog_http_quit_step(struct mog_fd *mfd)
         }
 }
 
-/* called immediately after accept(), this initializes the mfd (once) */
-void mog_http_post_accept(int fd, struct mog_svc *svc,
+/* stringify the address for tracers */
+static MOG_NOINLINE void
+trace_http_accepted(struct mog_fd *mfd, struct sockaddr *sa, socklen_t salen)
+{
+#ifdef HAVE_SYSTEMTAP
+        struct mog_ni ni;
+        int rc = mog_nameinfo(sa, salen, &ni);
+        const char *host = rc == 0 ? ni.ni_host : gai_strerror(rc);
+
+        TRACE(CMOGSTORED_HTTP_ACCEPTED(mfd->fd, host, ni.ni_serv));
+#endif /* !HAVE_SYSTEMTAP */
+}
+
+static void http_post_accept_common(struct mog_fd *mfd, struct mog_svc *svc,
                         struct sockaddr *sa, socklen_t salen)
 {
-        struct mog_fd *mfd = mog_fd_init(fd, MOG_FD_TYPE_HTTP);
         struct mog_http *http = &mfd->as.http;
 
+        if (TRACE_ENABLED(CMOGSTORED_HTTP_ACCEPTED))
+                trace_http_accepted(mfd, sa, salen);
+
         mog_http_init(http, svc);
         mog_packaddr_init(&http->mpa, sa, salen);
         mog_idleq_add(svc->queue, mfd, MOG_QEV_RD);
 }
 
 /* called immediately after accept(), this initializes the mfd (once) */
+void mog_http_post_accept(int fd, struct mog_svc *svc,
+                        struct sockaddr *sa, socklen_t salen)
+{
+        struct mog_fd *mfd = mog_fd_init(fd, MOG_FD_TYPE_HTTP);
+
+        http_post_accept_common(mfd, svc, sa, salen);
+}
+
+/* called immediately after accept(), this initializes the mfd (once) */
 void mog_httpget_post_accept(int fd, struct mog_svc *svc,
                         struct sockaddr *sa, socklen_t salen)
 {
         struct mog_fd *mfd = mog_fd_init(fd, MOG_FD_TYPE_HTTPGET);
-        struct mog_http *http = &mfd->as.http;
 
-        mog_http_init(http, svc);
-        mog_packaddr_init(&http->mpa, sa, salen);
-        mog_idleq_add(svc->queue, mfd, MOG_QEV_RD);
+        http_post_accept_common(mfd, svc, sa, salen);
 }
 
 /*
diff --git a/http_dav.c b/http_dav.c
index e61a83c..8503d45 100644
--- a/http_dav.c
+++ b/http_dav.c
@@ -8,12 +8,13 @@
 #include "cmogstored.h"
 #include "http.h"
 
-void mog_http_delete(struct mog_http *http, char *buf)
+void mog_http_delete(struct mog_fd *mfd, char *buf)
 {
+        struct mog_http *http = &mfd->as.http;
         int rc;
         char *path;
 
-        if (mog_fd_of(http)->fd_type == MOG_FD_TYPE_HTTPGET) {
+        if (mfd->fd_type == MOG_FD_TYPE_HTTPGET) {
                 mog_http_resp(http, "405 Method Not Allowed", true);
                 return;
         }
@@ -45,11 +46,12 @@ forbidden:
         } while(0));
 }
 
-void mog_http_mkcol(struct mog_http *http, char *buf)
+void mog_http_mkcol(struct mog_fd *mfd, char *buf)
 {
+        struct mog_http *http = &mfd->as.http;
         char *path;
 
-        if (mog_fd_of(http)->fd_type == MOG_FD_TYPE_HTTPGET) {
+        if (mfd->fd_type == MOG_FD_TYPE_HTTPGET) {
                 mog_http_resp(http, "405 Method Not Allowed", true);
                 return;
         }
diff --git a/http_get.c b/http_get.c
index cb3a6eb..e8f8f4a 100644
--- a/http_get.c
+++ b/http_get.c
@@ -180,8 +180,9 @@ bad_range:
         return (off_t)count;
 }
 
-void mog_http_get_open(struct mog_http *http, char *buf)
+void mog_http_get_open(struct mog_fd *mfd, char *buf)
 {
+        struct mog_http *http = &mfd->as.http;
         struct stat sb;
         struct mog_file *file = NULL;
         char *path = mog_http_path(http, buf);
diff --git a/http_put.c b/http_put.c
index a47d944..360c46e 100644
--- a/http_put.c
+++ b/http_put.c
@@ -362,12 +362,13 @@ static struct mog_file * open_put(struct mog_http *http, char *path)
         return file;
 }
 
-void mog_http_put(struct mog_http *http, char *buf, size_t buf_len)
+void mog_http_put(struct mog_fd *mfd, char *buf, size_t buf_len)
 {
+        struct mog_http *http = &mfd->as.http;
         char *path;
         struct mog_file *file;
 
-        if (mog_fd_of(http)->fd_type == MOG_FD_TYPE_HTTPGET) {
+        if (mfd->fd_type == MOG_FD_TYPE_HTTPGET) {
                 mog_http_resp(http, "405 Method Not Allowed", false);
                 return;
         }
diff --git a/m4/systemtap.m4 b/m4/systemtap.m4
new file mode 100644
index 0000000..dccb9b3
--- /dev/null
+++ b/m4/systemtap.m4
@@ -0,0 +1,37 @@
+dnl systemtap support
+dnl enable automatically if dtrace and sdt.h are available
+AC_DEFUN([CM_SYSTEMTAP],[
+AC_CHECK_PROGS(DTRACE, dtrace)
+AC_CHECK_HEADER([sys/sdt.h], [SDT_H_FOUND='yes'], [SDT_H_FOUND='no'])
+AS_IF([test "x${DTRACE}" != x && test $SDT_H_FOUND = yes],
+        AC_CACHE_CHECK([for sys/sdt.h usability],
+                        [cm_cv_sdt_h_usable], [
+                        AC_TRY_COMPILE([
+                                #include <sys/sdt.h>
+                                void foo(void) { STAP_PROBE(foo, foo); }
+                        ],[],
+                        [cm_cv_sdt_h_usable=yes],
+                        [cm_cv_sdt_h_usable=no])]))
+AS_IF([test $cm_cv_sdt_h_usable = yes],
+      [ENABLE_SYSTEMTAP=yes], [ENABLE_SYSTEMTAP=no])
+
+dnl support explicit --disable-systemtap or --enable-systemtap
+AC_MSG_CHECKING([whether to include systemtap tracing support])
+AC_ARG_ENABLE([systemtap],
+        [AS_HELP_STRING([--enable-systemtap],
+                        [Enable inclusion of systemtap trace support])],
+        [ENABLE_SYSTEMTAP="${enableval}"])
+AM_CONDITIONAL([ENABLE_SYSTEMTAP], [test x$ENABLE_SYSTEMTAP = xyes])
+AC_MSG_RESULT(${ENABLE_SYSTEMTAP})
+
+dnl maybe somebody forced --enable-systemtap w/o dtrace or sdt.h
+if test "x${ENABLE_SYSTEMTAP}" = xyes
+then
+        AS_IF([test "x${DTRACE}" = x], [AC_MSG_ERROR([dtrace not found])])
+        AS_IF([test $SDT_H_FOUND = no],
+              [ AC_MSG_ERROR([systemtap support needs sys/sdt.h header]) ])
+        AS_IF([test $cm_cv_sdt_h_usable = no],
+              [ AC_MSG_ERROR([sys/sdt.h header is not usable (clang?)]) ])
+        AC_DEFINE([HAVE_SYSTEMTAP], [1], [Define to 1 if using sdt probes.])
+fi
+])
diff --git a/mgmt.c b/mgmt.c
index 2fbef74..839a919 100644
--- a/mgmt.c
+++ b/mgmt.c
@@ -3,6 +3,7 @@
  * License: GPLv3 or later (see COPYING for details)
  */
 #include "cmogstored.h"
+#include "trace.h"
 #include "mgmt.h"
 #include "digest.h"
 #include "ioprio.h"
@@ -205,6 +206,7 @@ parse:
                         return mgmt->wbuf ? MOG_NEXT_WAIT_WR : MOG_NEXT_ACTIVE;
                 }
         } else if (r == 0) { /* client shut down */
+                TRACE(CMOGSTORED_MGMT_RDCLOSE(mfd, buf_len));
                 return MOG_NEXT_CLOSE;
         } else {
                 switch (errno) {
@@ -215,8 +217,11 @@ parse:
                 case EINTR: goto reread;
                 case ECONNRESET:
                 case ENOTCONN:
+                        /* these errors are too common to log, normally */
+                        TRACE(CMOGSTORED_MGMT_RDERR(mfd, buf_len, errno));
                         return MOG_NEXT_CLOSE;
                 default:
+                        TRACE(CMOGSTORED_MGMT_RDERR(mfd, buf_len, errno));
                         syslog(LOG_NOTICE, "mgmt client died: %m");
                         return MOG_NEXT_CLOSE;
                 }
@@ -268,6 +273,19 @@ void mog_mgmt_quit_step(struct mog_fd *mfd)
         }
 }
 
+/* stringify the address for tracers */
+static MOG_NOINLINE void
+trace_mgmt_accepted(struct mog_fd *mfd, struct sockaddr *sa, socklen_t salen)
+{
+#ifdef HAVE_SYSTEMTAP
+        struct mog_ni ni;
+        int rc = mog_nameinfo(sa, salen, &ni);
+        const char *host = rc == 0 ? ni.ni_host : gai_strerror(rc);
+
+        TRACE(CMOGSTORED_MGMT_ACCEPTED(mfd->fd, host, ni.ni_serv));
+#endif /* !HAVE_SYSTEMTAP */
+}
+
 /* called immediately after accept(), this initializes the mfd (once) */
 void mog_mgmt_post_accept(int fd, struct mog_svc *svc,
                         struct sockaddr *sa, socklen_t salen)
@@ -275,6 +293,9 @@ void mog_mgmt_post_accept(int fd, struct mog_svc *svc,
         struct mog_fd *mfd = mog_fd_init(fd, MOG_FD_TYPE_MGMT);
         struct mog_mgmt *mgmt = &mfd->as.mgmt;
 
+        if (TRACE_ENABLED(CMOGSTORED_MGMT_ACCEPTED))
+                trace_mgmt_accepted(mfd, sa, salen);
+
         mog_mgmt_init(mgmt, svc);
         mog_idleq_add(svc->queue, mfd, MOG_QEV_RD);
 }
diff --git a/probes.d b/probes.d
new file mode 100644
index 0000000..4be0d6c
--- /dev/null
+++ b/probes.d
@@ -0,0 +1,24 @@
+/*
+ * note: probe names are upper-case in the source and prefixed by provider
+ * So we'll have trace points like:
+ *  CMOGSTORED_HTTP_RDERR for the "http_rderr" trace point
+ *
+ * Warning: probe points are currently an unstable interface and likely
+ * to change in 2013
+ */
+provider cmogstored {
+        probe http_rderr(size_t buf_len, int err);
+        probe http_rdclose(size_t buf_len);
+        probe http_accepted(int fd, const char *host, const char *port);
+
+        probe http_req_begin(bool pipelined);
+        /* DWARF: http_process_client */
+        /* DWARF: mog_http_get_open */
+        probe http_req_end();
+
+        probe mgmt_accepted(int fd, const char *host, const char *port);
+        probe mgmt_rderr(struct mog_fd *mfd, size_t buf_len, int err);
+        probe mgmt_rdclose(struct mog_fd *mfd, size_t buf_len);
+
+        probe write_buffered();
+};
diff --git a/tapset/http_request.stp b/tapset/http_request.stp
new file mode 100644
index 0000000..2f1514a
--- /dev/null
+++ b/tapset/http_request.stp
@@ -0,0 +1,40 @@
+/* keyed by: [pid(),fd] */
+global cmogstored_http_req_begin;
+global cmogstored_http_pipelined;
+global cmogstored_http_addr;
+
+probe process("cmogstored").mark("http_accepted") {
+        fd = $arg1;
+        host = user_string($arg2);
+        serv = user_string($arg3);
+        host_serv = sprintf("%s%s", host, serv);
+        printf("% 8d accepted %s\n", fd, host_serv);
+        cmogstored_http_addr[pid(),fd] = host_serv;
+}
+
+probe process("cmogstored").function("http_close") {
+        fd = @cast($mfd, "struct mog_fd")->fd;
+        printf("% 8d closing\n", fd);
+        delete cmogstored_http_addr[pid(),fd];
+}
+
+probe process("cmogstored").mark("http_req_begin") {
+        fd = @cast($mfd, "struct mog_fd")->fd;
+        is_pipelined = $arg1;
+        cmogstored_http_req_begin[pid(),fd] = gettimeofday_us();
+        cmogstored_http_pipelined[pid(),fd] = is_pipelined;
+}
+
+probe process("cmogstored").function("http_process_client") {
+        fd = @cast($mfd, "struct mog_fd")->fd;
+        starttime = cmogstored_http_req_begin[pid(),fd];
+        diff = gettimeofday_us() - starttime;
+
+        is_pipelined = cmogstored_http_pipelined[pid(),fd];
+        printf("% 8d http_process_client time %ldus (pipelined:%s)\n",
+               fd, diff, is_pipelined ? "true" : "false");
+}
+
+probe process("cmogstored").mark("write_buffered") {
+        printf("% 8d blocked with %lu bytes to write\n", $fd, $len);
+}
diff --git a/trace.h b/trace.h
new file mode 100644
index 0000000..39dce9b
--- /dev/null
+++ b/trace.h
@@ -0,0 +1,8 @@
+#ifdef HAVE_SYSTEMTAP
+#  include "probes.h"
+#  define TRACE(probe) probe
+#  define TRACE_ENABLED(probe) probe ## _ENABLED()
+#else  /*  HAVE_SYSTEMTAP */
+#  define TRACE(probe)
+#  define TRACE_ENABLED(probe) (0)
+#endif /* !HAVE_SYSTEMTAP */
diff --git a/trywrite.c b/trywrite.c
index 4680d3c..d19f653 100644
--- a/trywrite.c
+++ b/trywrite.c
@@ -3,6 +3,7 @@
  * License: GPLv3 or later (see COPYING for details)
  */
 #include "cmogstored.h"
+#include "trace.h"
 
 struct mog_wbuf {
         size_t len;
@@ -76,30 +77,32 @@ enum mog_write_state mog_tryflush(int fd, struct mog_wbuf **x)
  */
 void * mog_trywritev(int fd, struct iovec *iov, int iovcnt)
 {
-        ssize_t total = 0;
+        ssize_t len = 0;
         ssize_t w;
         int i;
 
         for (i = 0; i < iovcnt; i++)
-                total += iov[i].iov_len;
+                len += iov[i].iov_len;
 
-        if (total == 0)
+        if (len == 0)
                 return NULL;
 retry:
         w = writev(fd, iov, iovcnt);
 
-        if (w == total) {
+        if (w == len) {
                 return NULL;
         } else if (w < 0) {
                 switch (errno) {
-                case_EAGAIN: return wbuf_newv(total, iov, iovcnt);
+                case_EAGAIN:
+                        TRACE(CMOGSTORED_WRITE_BUFFERED());
+                        return wbuf_newv(len, iov, iovcnt);
                 case EINTR: goto retry;
                 }
                 return MOG_WR_ERROR;
         } else {
                 struct iovec *new_iov = iov;
 
-                total -= w;
+                len -= w;
 
                  /* skip over iovecs we've already written completely */
                 for (i = 0; i < iovcnt; i++, new_iov++) {
@@ -147,7 +150,9 @@ void * mog_trysend(int fd, void *buf, size_t len, off_t more)
 
                         if (w < 0) {
                                 switch (errno) {
-                                case_EAGAIN: return wbuf_new(buf, len);
+                                case_EAGAIN:
+                                        TRACE(CMOGSTORED_WRITE_BUFFERED());
+                                        return wbuf_new(buf, len);
                                 case EINTR: continue;
                                 }
                                 return MOG_WR_ERROR;