flesh out systemtap support and awk helpers

Our "all.stp" tapset now generates awk-friendly output for feeding
some sample awk scripts.

Using awk (and gawk) was necessary to avoid reimplementing strftime
in guru mode for generating CLF (Common Log Format) HTTP access logs.

Using awk also gives us several advantages:

* floating point number support (for time differences)

* a more familiar language to systems administrators
  (given this is for MogileFS, perhaps Perl would be even
   more familiar...).

* fast edit/run cycle, so the slowness of using stap to
  rebuild/reload the kernel module for all.stp changes can
  be avoided when output must be customized.

13 files changed, 311 insertions, 114 deletions

diff --git a/http.c b/http.c
index 3ec62a6..547fdb1 100644
--- a/http.c
+++ b/http.c
@@ -205,7 +205,7 @@ static enum mog_next http_run(struct mog_fd *mfd, struct mog_rbuf *rbuf,
         } else {
                 /* pipelined request */
                 if (buf_len)
-                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(true));
+                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(mfd->fd, true));
 
                 http_defer_rbuf(http, rbuf, buf_len);
                 mog_http_reset(mfd);
@@ -219,7 +219,7 @@ http_client_died(struct mog_fd *mfd, size_t buf_len, int save_err)
         struct mog_ni ni;
 
         /* TODO: support nameinfo */
-        TRACE(CMOGSTORED_HTTP_RDERR(buf_len, save_err));
+        TRACE(CMOGSTORED_HTTP_RDERR(mfd->fd, buf_len, save_err));
 
         switch (save_err) {
         case ECONNRESET:
@@ -240,6 +240,7 @@ http_rbuf_grow(struct mog_fd *mfd, struct mog_rbuf **rbuf, size_t buf_len)
 {
         struct mog_http *http = &mfd->as.http;
 
+        TRACE(CMOGSTORED_HTTP_RBUF_GROW(mfd->fd, buf_len));
         (*rbuf)->rsize = buf_len;
         http->rbuf = *rbuf = mog_rbuf_grow(*rbuf);
         return *rbuf ? (*rbuf)->rptr : NULL;
@@ -251,6 +252,7 @@ http_parse_continue(struct mog_fd *mfd, struct mog_rbuf **rbuf,
 {
         struct mog_http *http = &mfd->as.http;
 
+        TRACE(CMOGSTORED_HTTP_PARSE_CONTINUE(mfd->fd, buf_len));
         assert(http->wbuf == NULL &&
                "tried to write (and failed) with partial req");
         if (http->_p.buf_off >= (*rbuf)->rcapa) {
@@ -302,7 +304,7 @@ reread:
         r = read(mfd->fd, buf + off, rbuf->rcapa - off);
         if (r > 0) {
                 if (off == 0)
-                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(false));
+                        TRACE(CMOGSTORED_HTTP_REQ_BEGIN(mfd->fd, false));
 
                 buf_len = r + off;
 parse:
@@ -320,7 +322,7 @@ parse:
                         return http_run(mfd, rbuf, buf, buf_len);
                 }
         } else if (r == 0) { /* client shut down */
-                TRACE(CMOGSTORED_HTTP_RDCLOSE(buf_len));
+                TRACE(CMOGSTORED_HTTP_CLIENT_CLOSE(mfd->fd, buf_len));
                 return MOG_NEXT_CLOSE;
         } else {
                 switch (errno) {
@@ -476,10 +478,18 @@ void mog_http_resp0(struct mog_fd *mfd, struct iovec *status, bool alive)
         struct mog_http *http = &mfd->as.http;
 
         assert(status->iov_len * 2 + 1024 < iov.iov_len && "fsbuf too small");
+        assert(status->iov_len > 3 && "HTTP response status too short");
 
 #define CPY(str) mempcpy(dst, (str),(sizeof(str)-1))
         dst = CPY("HTTP/1.1 ");
         dst = mempcpy(dst, status->iov_base, status->iov_len);
+
+        /*
+         * putting this here avoids systemtap faults, as status->iov_base
+         * is already hot in cache from the above mempcpy
+         */
+        TRACE(CMOGSTORED_HTTP_RES_START(mfd->fd, status->iov_base));
+
         dst = CPY("\r\nDate: ");
         now = mog_now();
         dst = mempcpy(dst, now->httpdate, sizeof(now->httpdate)-1);
@@ -502,6 +512,7 @@ void mog_http_resp0(struct mog_fd *mfd, struct iovec *status, bool alive)
 /* call whenever we're ready to read the next HTTP request */
 void mog_http_reset(struct mog_fd *mfd)
 {
+        TRACE(CMOGSTORED_HTTP_RES_DONE(mfd->fd));
         tcp_push(mfd, true);
         mog_http_reset_parser(&mfd->as.http);
 }
diff --git a/http_dav.c b/http_dav.c
index 94e7773..037844c 100644
--- a/http_dav.c
+++ b/http_dav.c
@@ -24,6 +24,8 @@ void mog_http_delete(struct mog_fd *mfd, char *buf)
         assert(path[0] == '/' && "bad path");
         if (path[1] == '\0') goto forbidden;
 
+        TRACE(CMOGSTORED_HTTP_REQ_START(mfd->fd, "DELETE", path));
+
         rc = mog_unlink(http->svc, path);
         if (rc == 0) {
                 mog_http_resp(mfd, "204 No Content", true);
@@ -58,6 +60,12 @@ void mog_http_mkcol(struct mog_fd *mfd, char *buf)
         path = mog_http_path(http, buf);
 
         /*
+         * This can be useful for making sure the skip_mkcol server setting
+         * is enabled in the tracker/database to avoid latency
+         */
+        TRACE(CMOGSTORED_HTTP_REQ_START(mfd->fd, "MKCOL", path));
+
+        /*
          * Do not do anything on MKCOL and rely on PUT to create
          * directories.  This stops MogileFS trackers from trying
          * (expensive) MKCOL requests.  Perlbal/mogstored also does
diff --git a/http_get.c b/http_get.c
index 98735f0..acca0df 100644
--- a/http_get.c
+++ b/http_get.c
@@ -48,7 +48,7 @@ static off_t http_get_resp_hdr(struct mog_fd *mfd, struct stat *sb)
 {
         struct mog_http *http = &mfd->as.http;
         char *modified;
-        void *buf;
+        char *buf;
         size_t len;
         struct mog_now *now = mog_now();
         long long count;
@@ -56,7 +56,7 @@ static off_t http_get_resp_hdr(struct mog_fd *mfd, struct stat *sb)
 
         /* single buffer so we can use MSG_MORE */
         buf = mog_fsbuf_get(&len);
-        modified = (char *)buf + len / 2;
+        modified = buf + len / 2;
         assert((len / 2) > MOG_HTTPDATE_CAPA && "fsbuf too small");
         mog_http_date(modified, MOG_HTTPDATE_CAPA, &sb->st_mtime);
 
@@ -174,6 +174,8 @@ bad_range:
         if (http->_p.http_method == MOG_HTTP_METHOD_HEAD)
                 count = 0;
 
+
+        TRACE(CMOGSTORED_HTTP_RES_START(mfd->fd, buf + sizeof("HTTP/1.1")));
         http->wbuf = mog_trysend(mfd->fd, buf, len, (off_t)count);
 
         return (off_t)count;
@@ -191,6 +193,9 @@ void mog_http_get_open(struct mog_fd *mfd, char *buf)
         assert(http->forward == NULL && "already have http->forward");
         assert(path[0] == '/' && "bad path");
 
+        TRACE(CMOGSTORED_HTTP_REQ_START(mfd->fd,
+                http->_p.http_method == MOG_HTTP_METHOD_HEAD ?
+                "HEAD" : "GET", path));
         if (path[1] == '\0') { /* keep "mogadm check" happy */
                 sb.st_mtime = 0;
                 sb.st_size = 0;
@@ -284,6 +289,7 @@ retry:
                        (long long)file->foff);
         }
 done:
+        TRACE(CMOGSTORED_HTTP_BYTES_XFER(mfd->fd, file->foff));
         mog_file_close(http->forward);
         if (http->_p.persistent) {
                 mog_http_reset(mfd);
diff --git a/http_put.c b/http_put.c
index da21f64..0072fca 100644
--- a/http_put.c
+++ b/http_put.c
@@ -19,6 +19,7 @@ static void file_close_null(struct mog_fd *mfd)
         if (http->forward == NULL)
                 return;
         mog_http_unlink_ftmp(http);
+        TRACE(CMOGSTORED_HTTP_BYTES_XFER(mfd->fd, http->forward->as.file.foff));
         mog_file_close(http->forward);
         http->forward = NULL;
 }
@@ -379,6 +380,8 @@ void mog_http_put(struct mog_fd *mfd, char *buf, size_t buf_len)
         assert(http->forward == NULL && "already have http->forward");
         assert(path[0] == '/' && "bad path");
 
+        TRACE(CMOGSTORED_HTTP_REQ_START(mfd->fd, "PUT", path));
+
         if (!lengths_ok(http)) {
                 write_err(mfd, "400 Bad Request");
                 return;
diff --git a/ioq.c b/ioq.c
index 339ef3d..78a9ba7 100644
--- a/ioq.c
+++ b/ioq.c
@@ -100,6 +100,7 @@ bool mog_ioq_ready(struct mog_ioq *ioq, struct mog_fd *mfd)
 
                 mog_ioq_current = ioq;
         } else {
+                TRACE(CMOGSTORED_IOQ_BLOCKED(mfd->fd));
                 mfd->ioq_blocked = 1;
                 SIMPLEQ_INSERT_TAIL(&ioq->ioq_head, mfd, ioqent);
                 ioq_set_contended(ioq);
@@ -213,6 +214,7 @@ bool mog_ioq_unblock(struct mog_fd *mfd)
         if (mfd->ioq_blocked == 0)
                 return false;
 
+        TRACE(CMOGSTORED_IOQ_UNBLOCKED(mfd->fd));
         mfd->ioq_blocked = 0;
         return true;
 }
diff --git a/mgmt.c b/mgmt.c
index bc6b335..df840bf 100644
--- a/mgmt.c
+++ b/mgmt.c
@@ -37,10 +37,10 @@ static void mgmt_digest_step(struct mog_fd *mfd)
         case MOG_DIGEST_YIELD:
                 return;
         case MOG_DIGEST_EOF:
-                mog_mgmt_fn_digest_emit(mgmt);
+                mog_mgmt_fn_digest_emit(mfd);
                 break;
         case MOG_DIGEST_ERROR:
-                mog_mgmt_fn_digest_err(mgmt);
+                mog_mgmt_fn_digest_err(mfd);
         }
 
         mog_file_close(mgmt->forward);
@@ -183,7 +183,7 @@ mgmt_process_client(struct mog_fd *mfd, struct mog_rbuf *rbuf,
                 mog_mgmt_fn_size(mgmt, buf);
                 break;
         case MOG_MGMT_METHOD_DIG:
-                mog_mgmt_fn_digest(mgmt, buf);
+                mog_mgmt_fn_digest(mfd, buf);
 
                 if (dev && mgmt->forward)
                         assert(mgmt->forward->as.file.ioq
@@ -217,6 +217,8 @@ static char *
 mgmt_rbuf_grow(struct mog_fd *mfd, struct mog_rbuf **rbuf, size_t buf_len)
 {
         struct mog_mgmt *mgmt = &mfd->as.mgmt;
+
+        TRACE(CMOGSTORED_MGMT_RBUF_GROW(mfd->fd, buf_len));
         (*rbuf)->rsize = buf_len;
         mgmt->rbuf = *rbuf = mog_rbuf_grow(*rbuf);
         return *rbuf ? (*rbuf)->rptr : NULL;
@@ -228,6 +230,8 @@ mgmt_parse_continue(struct mog_fd *mfd, struct mog_rbuf **rbuf,
 {
         struct mog_mgmt *mgmt = &mfd->as.mgmt;
 
+        TRACE(CMOGSTORED_MGMT_PARSE_CONTINUE(mfd->fd, buf_len));
+
         assert(mgmt->wbuf == NULL &&
                "tried to write (and failed) with partial req");
         if (mgmt->buf_off >= (*rbuf)->rcapa) {
@@ -296,7 +300,7 @@ parse:
                         return mgmt_run(mfd, rbuf, buf, buf_len);
                 }
         } else if (r == 0) { /* client shut down */
-                TRACE(CMOGSTORED_MGMT_RDCLOSE(mfd, buf_len));
+                TRACE(CMOGSTORED_MGMT_CLIENT_CLOSE(mfd->fd, buf_len));
                 return MOG_NEXT_CLOSE;
         } else {
                 switch (errno) {
@@ -311,10 +315,10 @@ parse:
                 case ECONNRESET:
                 case ENOTCONN:
                         /* these errors are too common to log, normally */
-                        TRACE(CMOGSTORED_MGMT_RDERR(mfd, buf_len, errno));
+                        TRACE(CMOGSTORED_MGMT_RDERR(mfd->fd, buf_len, errno));
                         return MOG_NEXT_CLOSE;
                 default:
-                        TRACE(CMOGSTORED_MGMT_RDERR(mfd, buf_len, errno));
+                        TRACE(CMOGSTORED_MGMT_RDERR(mfd->fd, buf_len, errno));
                         syslog(LOG_NOTICE, "mgmt client died: %m");
                         return MOG_NEXT_CLOSE;
                 }
diff --git a/mgmt.h b/mgmt.h
index b4ecb9d..7cb0a05 100644
--- a/mgmt.h
+++ b/mgmt.h
@@ -12,11 +12,11 @@ enum mog_parser_state mog_mgmt_parse(struct mog_mgmt *, char *buf, size_t len);
 void mog_mgmt_reset_parser(struct mog_mgmt *);
 
 /* mgmt_fn.c */
-void mog_mgmt_fn_digest(struct mog_mgmt *, char *buf);
+void mog_mgmt_fn_digest(struct mog_fd *, char *buf);
 void mog_mgmt_fn_size(struct mog_mgmt *, char *buf);
 void mog_mgmt_fn_blank(struct mog_mgmt *);
 void mog_mgmt_fn_unknown(struct mog_mgmt *, char *buf);
 void mog_mgmt_fn_watch_err(struct mog_mgmt *);
-void mog_mgmt_fn_digest_emit(struct mog_mgmt *);
-void mog_mgmt_fn_digest_err(struct mog_mgmt *);
+void mog_mgmt_fn_digest_emit(struct mog_fd *);
+void mog_mgmt_fn_digest_err(struct mog_fd *);
 void mog_mgmt_fn_aio_threads(struct mog_mgmt *, char *);
diff --git a/mgmt_fn.c b/mgmt_fn.c
index 8bdec2d..b1cc50a 100644
--- a/mgmt_fn.c
+++ b/mgmt_fn.c
@@ -35,13 +35,16 @@ get_path(struct iovec *dst, struct mog_mgmt *mgmt, char *buf, bool sdup)
 }
 
 /* starts the MD5 request */
-void mog_mgmt_fn_digest(struct mog_mgmt *mgmt, char *buf)
+void mog_mgmt_fn_digest(struct mog_fd *mfd, char *buf)
 {
+        struct mog_mgmt *mgmt = &mfd->as.mgmt;
         struct iovec iov[2];
         char *path = get_path(iov, mgmt, buf, true);
 
         if (!path) return;
 
+        TRACE(CMOGSTORED_MGMT_DIG_START(mfd->fd, mgmt->alg, path));
+
         mgmt->forward = mog_file_open_read(mgmt->svc, path);
         if (mgmt->forward) {
                 struct mog_file *file = &mgmt->forward->as.file;
@@ -62,6 +65,7 @@ void mog_mgmt_fn_digest(struct mog_mgmt *mgmt, char *buf)
                 default: /* Ragel parser prevents this: */
                         die("BUG: unhandled algorithm: %d", mgmt->alg);
                 }
+                TRACE(CMOGSTORED_MGMT_DIG_DONE(mfd->fd, -1));
                 mog_mgmt_writev(mgmt, iov, 2);
                 free(path);
         }
@@ -70,12 +74,13 @@ void mog_mgmt_fn_digest(struct mog_mgmt *mgmt, char *buf)
 /* finishes the MD5 request */
 #define CLEN(s) (sizeof(s)-1)
 
-void mog_mgmt_fn_digest_err(struct mog_mgmt *mgmt)
+void mog_mgmt_fn_digest_err(struct mog_fd *mfd)
 {
+        struct mog_mgmt *mgmt = &mfd->as.mgmt;
         struct iovec iov[3];
-        struct mog_fd *mfd = mgmt->forward;
-        struct mog_file *file = &mfd->as.file;
-        long long offset = (long long)lseek(mfd->fd, 0, SEEK_CUR);
+        struct mog_fd *file_mfd = mgmt->forward;
+        struct mog_file *file = &file_mfd->as.file;
+        long long offset = (long long)lseek(file_mfd->fd, 0, SEEK_CUR);
         char buf[sizeof(" at 18446744073709551615 failed\r\n") - 1];
 
         /* offset could be -1 here, but there ain't much we can do */
@@ -86,17 +91,19 @@ void mog_mgmt_fn_digest_err(struct mog_mgmt *mgmt)
         iov[2].iov_base = buf;
         iov[2].iov_len = snprintf(buf, sizeof(buf),
                                   " at %lld failed\r\n", offset);
+        TRACE(CMOGSTORED_MGMT_DIG_DONE(mfd->fd, offset));
         mog_mgmt_writev(mgmt, iov, 3);
 }
 
 /* output: "/$PATH MD5=hex\r\n" */
-void mog_mgmt_fn_digest_emit(struct mog_mgmt *mgmt)
+void mog_mgmt_fn_digest_emit(struct mog_fd *mfd)
 {
+        struct mog_mgmt *mgmt = &mfd->as.mgmt;
         struct iovec iov[2];
         char buf[CLEN(" SHA-1=") + 40 + CLEN("\r\n")];
         char *b = buf;
-        struct mog_fd *mfd = mgmt->forward;
-        struct mog_file *file = &mfd->as.file;
+        struct mog_fd *file_mfd = mgmt->forward;
+        struct mog_file *file = &file_mfd->as.file;
         size_t len;
 
         iov[0].iov_base = file->path;
@@ -122,6 +129,7 @@ void mog_mgmt_fn_digest_emit(struct mog_mgmt *mgmt)
         b[len] = '\r';
         b[len + 1] = '\n';
         iov[1].iov_base = buf;
+        TRACE(CMOGSTORED_MGMT_DIG_DONE(mfd->fd, 0));
         mog_mgmt_writev(mgmt, iov, 2);
 }
 
diff --git a/probes.d b/probes.d
index d6197d6..a0d7b58 100644
--- a/probes.d
+++ b/probes.d
@@ -7,29 +7,33 @@
  * to change in 2013
  */
 provider cmogstored {
-        probe http_rderr(size_t buf_len, int err);
-        probe http_rdclose(size_t buf_len);
+        probe http_rderr(int fd, size_t buf_len, int err);
+        probe http_rdclose(int fd, size_t buf_len);
         probe http_accepted(int fd, const char *host, const char *port,
                                 const char *listen_addr);
 
-        probe http_req_begin(bool pipelined);
-        /* DWARF: http_process_client */
-        /* DWARF: mog_http_get_open */
-        probe http_req_end();
+        probe http_req_begin(int fd, bool pipelined);
 
-        /* DWARF: mog_ioq_ready(.return) */
+        probe http_parse_continue(int fd, size_t buf_len);
+        probe http_rbuf_grow(int fd, size_t buf_len);
+        probe http_req_start(int fd, const char *method, const char *path);
+        probe http_res_start(int fd, const char *status);
+        probe http_res_done(int fd);
+        probe http_client_close(int fd, size_t buf_len);
+        probe http_bytes_xfer(int fd, off_t len);
+
+        probe ioq_blocked(int fd);
         probe ioq_reschedule(int fd);
-        /* DWARF: mog_ioq_unblock(.return) */
+        probe ioq_unblocked(int fd);
 
         probe mgmt_accepted(int fd, const char *host, const char *port,
                                 const char *listen_addr);
-        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();
+        probe mgmt_dig_start(int fd, int alg, const char *path);
+        probe mgmt_dig_done(int fd, long long code);
+        probe mgmt_parse_continue(int fd, size_t buf_len);
+        probe mgmt_rbuf_grow(int fd, size_t buf_len);
+        probe mgmt_rderr(int fd, size_t buf_len, int err);
+        probe mgmt_client_close(int fd, size_t buf_len);
 
-        /* DWARF: mgmt_rbuf_grow */
-        /* DWARF: mgmt_parse_continue */
-        /* DWARF: http_rbuf_grow */
-        /* DWARF: http_parse_continue */
+        probe write_buffered(int fd, size_t buf_len);
 };
diff --git a/tapset/all.stp b/tapset/all.stp
index 600c07a..0b9e194 100644
--- a/tapset/all.stp
+++ b/tapset/all.stp
@@ -1,129 +1,165 @@
 /*
  * This is an extremely detailed tapset for capturing all supported probe
  * points in the current version of cmogstored.  It likely contains too much
- * information to be useful, extracting relevant probes is recommended.
+ * information to be useful, extracting relevant probes is recommended,
+ * as is filtering this through an awk (or your favorite scripting language)
  */
 
-/* keyed by: [pid(),fd] */
-global cmogstored_http_req_begin;
-global cmogstored_http_pipelined;
-global cmogstored_http_addr;
-global cmogstored_fd_by_tid;
+/* avoid triggering copy faults because systemtap avoids page faults */
+function cmogstored_user_string(a) {
+        try {
+                s = user_string(a);
+        } catch {
+                s = "???";
+        }
+        return s;
+}
 
 probe process("cmogstored").mark("http_accepted") {
         fd = $arg1;
-        host = user_string($arg2);
-        serv = user_string($arg3);
-        listen = user_string($arg4);
-        host_serv = sprintf("%s%s", host, serv);
-        printf("% 6d % 6d accepted %s on %s\n", pid(), fd, host_serv, listen);
-        cmogstored_http_addr[pid(),fd] = host_serv;
+        host = cmogstored_user_string($arg2);
+        serv = cmogstored_user_string($arg3);
+        listen = cmogstored_user_string($arg4);
+        printf("% 6d % 6d http_accepted %s %s %s\n",
+                pid(), fd, host, serv, listen);
 }
 
 /*
- * mog_ioq_ready..ioq_reschedule   = time waiting for others to finish IO
- * ioq_reschedule..mog_ioq_unblock = time inside epoll ready list
+ * ioq_blocked..ioq_reschedule   = time waiting for others to finish IO
+ * ioq_reschedule..ioq_unblocked = time inside epoll ready list
  */
+probe process("cmogstored").mark("ioq_blocked") {
+        fd = $arg1;
+        printf("% 6d % 6d ioq_blocked %u\n", pid(), fd, gettimeofday_us());
+}
 
-/* associate the fd with thread for the function return */
-probe process("cmogstored").function("mog_ioq_ready") {
-        cmogstored_fd_by_tid[tid()] = @cast($mfd, "struct mog_fd")->fd;
+probe process("cmogstored").mark("http_req_start") {
+        fd = $arg1;
+        method = cmogstored_user_string($arg2);
+        path = cmogstored_user_string($arg3);
+        printf("% 6d % 6d http_req_start %s %s\n", pid(), fd, method, path);
 }
 
-/*
- * if mog_ioq_ready returns false, we are blocked waiting on I/O and
- * will hit ioq_reschedule
- */
-probe process("cmogstored").function("mog_ioq_ready").return {
-        if (!$return)
-                printf("% 6d % 6d ioq blocked\n",
-                        pid(), cmogstored_fd_by_tid[tid()]);
+probe process("cmogstored").mark("http_res_start") {
+        fd = $arg1;
+        try {
+                code = user_string_n($arg2, 3);
+        } catch {
+                code = "???";
+        }
+        printf("% 6d % 6d http_res_start %s\n", pid(), fd, code);
 }
 
 /*
  * we hit ioq_reschedule when we are ready to enter the epoll ready-list
- * we will hit mog_ioq_unblock eventually
+ * we will hit ioq_unblocked eventually
  */
 probe process("cmogstored").mark("ioq_reschedule") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d ioq reschedule_enter\n", pid(), fd);
-}
-
-/* associate the fd with thread for the function return */
-probe process("cmogstored").function("mog_ioq_unblock") {
-        cmogstored_fd_by_tid[tid()] = @cast($mfd, "struct mog_fd")->fd;
+        fd = $arg1;
+        printf("% 6d % 6d ioq_reschedule %u\n", pid(), fd, gettimeofday_us());
 }
 
 /*
- * if mog_ioq_unblock returns true, it means the fd was previously
+ * if ioq_unblock returns true, it means the fd was previously
  * in ioq_reschedule
  */
-probe process("cmogstored").function("mog_ioq_unblock").return {
-        if ($return)
-                printf("% 6d % 6d ioq reschedule_done\n",
-                        pid(), cmogstored_fd_by_tid[tid()]);
+probe process("cmogstored").mark("ioq_unblocked") {
+        fd = $arg1;
+        printf("% 6d % 6d ioq_unblocked %u\n", pid(), fd, gettimeofday_us());
 }
 
 /*
  * HTTP client disconnected
  */
-probe process("cmogstored").function("http_close") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d closing\n", pid(), fd);
-        delete cmogstored_http_addr[pid(),fd];
+probe process("cmogstored").mark("http_client_close") {
+        fd = $arg1;
+        printf("% 6d % 6d http_client_close\n", pid(), fd);
 }
 
 /*
  * We start reading/buffering the HTTP request here
  */
 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;
-}
-
-/*
- * we start processing the HTTP request (opening/stat-ing files)
- */
-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("% 6d % 6d http_process_client time %ldus (pipelined:%s)\n",
-                pid(), fd, diff, is_pipelined ? "true" : "false");
+        fd = $arg1;
+        is_pipelined = $arg2;
+        printf("% 6d % 6d http_req_begin %u %u\n",
+                pid(), fd, gettimeofday_us(), is_pipelined);
 }
 
 /*
  * We blocked on writing (HTTP headers) to the client socket
  */
 probe process("cmogstored").mark("write_buffered") {
-        printf("% 6d % 6d blocked with %lu bytes to write\n",
-                pid(), $fd, $len);
+        fd = $arg1;
+        len = $arg2;
+        printf("% 6d % 6d write_buffered %lu\n", pid(), fd, len);
 }
 
 /* signals a client is making us reallocate on large requests */
-probe process("cmogstored").function("http_rbuf_grow") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d http_rbuf_grow %lu\n", pid(), fd, $buf_len);
+probe process("cmogstored").mark("http_rbuf_grow") {
+        fd = $arg1;
+        buf_len = $arg2;
+        printf("% 6d % 6d http_rbuf_grow %lu\n", pid(), fd, buf_len);
 }
 
 /* signals a client is making us reallocate on large requests */
-probe process("cmogstored").function("mgmt_rbuf_grow") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d mgmt_rbuf_grow %lu\n", pid(), fd, $buf_len);
+probe process("cmogstored").mark("mgmt_rbuf_grow") {
+        fd = $arg1;
+        buf_len = $arg2;
+        printf("% 6d % 6d mgmt_rbuf_grow %lu\n", pid(), fd, buf_len);
 }
 
 /* this signals a client is trickling requests to us */
-probe process("cmogstored").function("http_parse_continue") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d http_parse_continue %lu\n", pid(), fd, $buf_len);
+probe process("cmogstored").mark("http_parse_continue") {
+        fd = $arg1;
+        buf_len = $arg2;
+        printf("% 6d % 6d http_parse_continue %lu\n", pid(), fd, buf_len);
 }
 
 /* this signals a client is trickling requests to us */
-probe process("cmogstored").function("mgmt_parse_continue") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
-        printf("% 6d % 6d mgmt_parse_continue %lu\n", pid(), fd, $buf_len);
+probe process("cmogstored").mark("mgmt_parse_continue") {
+        fd = $arg1;
+        buf_len = $arg2;
+        printf("% 6d % 6d mgmt_parse_continue %lu\n", pid(), fd, buf_len);
+}
+
+probe process("cmogstored").mark("mgmt_dig_start") {
+        fd = $arg1;
+
+        /* ref: lib/gc.h from gnulib */
+        if ($arg2 == 1) {
+                alg = "MD5";
+        } else if ($arg2 == 2) {
+                alg = "SHA-1";
+        } else {
+                alg = sprintf("???=%d", $arg2);
+        }
+
+        path = cmogstored_user_string($arg3);
+        printf("% 6d % 6d mgmt_dig_start %s %s\n", pid(), fd, alg, path);
+}
+
+probe process("cmogstored").mark("mgmt_dig_done") {
+        fd = $arg1;
+        if ($arg2 == 0) {
+                printf("% 6d % 6d mgmt_dig_done OK\n", pid(), fd);
+        } else if ($arg2 == -1) {
+                printf("% 6d % 6d mgmt_dig_done MISSING\n",
+                        pid(), fd);
+        } else {
+                printf("% 6d % 6d mgmt_dig_done fail_offset=%ld\n",
+                        pid(), fd, $arg2);
+        }
+}
+
+probe process("cmogstored").mark("http_bytes_xfer") {
+        fd = $arg1;
+        bytes = $arg2;
+
+        printf("% 6d % 6d http_bytes_xfer %d\n", pid(), fd, bytes);
+}
+
+probe process("cmogstored").mark("http_res_done") {
+        fd = $arg1;
+        printf("% 6d % 6d http_res_done %u\n", pid(), fd, gettimeofday_us());
 }
diff --git a/tapset/http_access_log.gawk b/tapset/http_access_log.gawk
new file mode 100755
index 0000000..fe2a616
--- /dev/null
+++ b/tapset/http_access_log.gawk
@@ -0,0 +1,62 @@
+#!/usr/bin/gawk -f
+# using gawk for strftime
+# This takes the output of the all.stp tapset distributed with cmogstored
+/ http_accepted / {
+        pid = $1
+        fd = $2
+        remote_addr = $4
+        http_addr[pid,fd] = remote_addr
+}
+
+/ http_req_begin / {
+        pid = $1
+        fd = $2
+        start_time = $4
+        http_bytes_xfer[pid,fd] = "-"
+        http_req_begin[pid,fd] = start_time
+}
+
+/ http_req_start / {
+        pid = $1
+        fd = $2
+        method = $4
+        path = $5
+        http_req_start[pid,fd] = method " " path
+}
+
+/ http_res_start / {
+        pid = $1
+        fd = $2
+        code = $4
+        http_res_start[pid,fd] = code
+}
+
+/ http_bytes_xfer / {
+        pid = $1
+        fd = $2
+        bytes = $4
+        http_bytes_xfer[pid,fd] = bytes
+}
+
+/ http_res_done / {
+        pid = $1
+        fd = $2
+        now_us = $4
+        now_s = now_us / 1000000
+        start_time = http_req_begin[pid,fd]
+        bytes = http_bytes_xfer[pid,fd]
+        remote_addr = http_addr[pid,fd]
+        request = http_req_start[pid,fd]
+        code = http_res_start[pid,fd]
+        now = strftime("%d/%b/%Y:%H:%M:%S +0000", now_s)
+
+        if (ELAPSED_TIME) {
+                # the elapsed time is not part of CLF, but I personally find
+                # log files worthless without it, so this is an option
+                elapsed = sprintf(" %0.4f", (now_us - start_time)/1000000)
+        } else {
+                elapsed = ""
+        }
+        print(remote_addr " - - [" now "] \"" \
+              request " HTTP/1.1\" " code" "bytes elapsed)
+}
diff --git a/tapset/ioq_wait.awk b/tapset/ioq_wait.awk
new file mode 100755
index 0000000..ba3913e
--- /dev/null
+++ b/tapset/ioq_wait.awk
@@ -0,0 +1,53 @@
+#!/usr/bin/awk -f
+/ ioq_blocked / {
+        pid = $1
+        fd = $2
+        time = $4
+        ioq_blocked[pid, fd] = time
+}
+
+/ ioq_reschedule / {
+        pid = $1
+        fd = $2
+        time = $4
+        ioq_reschedule[pid, fd] = time
+}
+
+/ http_req_start / {
+        pid = $1
+        fd = $2
+        method = $4
+        path = $5
+
+        now = ioq_unblocked[pid, fd]
+        if (now) {
+                blocked = (now - ioq_blocked[pid, fd]) / 1000000
+                resched = (now - ioq_reschedule[pid, fd]) / 1000000
+
+                printf("% 6d % 6d %0.4f %0.4f %s %s\n",
+                        pid, fd, blocked, resched, method, path)
+        }
+}
+
+/ mgmt_dig_start / {
+        pid = $1
+        fd = $2
+        alg = $4
+        path = $5
+
+        now = ioq_unblocked[pid, fd]
+        if (now) {
+                blocked = (now - ioq_blocked[pid, fd]) / 1000000
+                resched = (now - ioq_reschedule[pid, fd]) / 1000000
+
+                printf("% 6d % 6d %0.4f %0.4f %s %s\n",
+                        pid, fd, blocked, resched, alg, path)
+        }
+}
+
+/ ioq_unblocked / {
+        pid = $1
+        fd = $2
+        now = $4
+        ioq_unblocked[pid, fd] = now
+}
diff --git a/trywrite.c b/trywrite.c
index 1325e8c..2da4e01 100644
--- a/trywrite.c
+++ b/trywrite.c
@@ -98,7 +98,7 @@ retry:
         } else if (w <= 0) {
                 switch (errno) {
                 case_EAGAIN:
-                        TRACE(CMOGSTORED_WRITE_BUFFERED());
+                        TRACE(CMOGSTORED_WRITE_BUFFERED(fd, len));
                         return wbuf_newv(len, iov, iovcnt);
                 case EINTR: goto retry;
                 case 0: sysbug("writev", w);
@@ -165,7 +165,7 @@ void * mog_trysend(int fd, void *buf, size_t len, off_t more)
                          */
                         switch (errno) {
                         case_EAGAIN:
-                                TRACE(CMOGSTORED_WRITE_BUFFERED());
+                                TRACE(CMOGSTORED_WRITE_BUFFERED(fd, len));
                                 return wbuf_new(buf, len);
                         case EINTR: continue;
                         case 0: sysbug("send", w);