more probes WIP st-wip-broken

10 files changed, 96 insertions, 82 deletions

diff --git a/http.c b/http.c
index 2f3b29b..a122372 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) {
@@ -475,7 +477,10 @@ void mog_http_resp0(struct mog_fd *mfd, struct iovec *status, bool alive)
         char *dst = iov.iov_base = mog_fsbuf_get(&iov.iov_len);
         struct mog_http *http = &mfd->as.http;
 
+        TRACE(CMOGSTORED_HTTP_RES_START(mfd->fd, status->iov_base));
+
         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 ");
diff --git a/http_dav.c b/http_dav.c
index 94e7773..fcf8897 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);
@@ -55,9 +57,16 @@ void mog_http_mkcol(struct mog_fd *mfd, char *buf)
                 mog_http_resp(mfd, "405 Method Not Allowed", true);
                 return;
         }
+
         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 252ec5c..d774dfb 100644
--- a/http_get.c
+++ b/http_get.c
@@ -194,6 +194,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;
diff --git a/http_put.c b/http_put.c
index da21f64..a7c3df4 100644
--- a/http_put.c
+++ b/http_put.c
@@ -92,6 +92,9 @@ stop0(struct mog_fd *mfd, const char *status, size_t status_len)
         return MOG_NEXT_CLOSE;
 }
 
+static const char err507[] = "507 Insufficient Storage";
+static const char err500[] = "500 Internal Server Error";
+
 MOG_NOINLINE static enum mog_next
 write_err(struct mog_fd *mfd, const char *default_msg)
 {
@@ -99,11 +102,11 @@ write_err(struct mog_fd *mfd, const char *default_msg)
         case ERANGE:
         case ENOSPC:
         case EFBIG:
-                return stop(mfd, "507 Insufficient Storage");
+                return stop(mfd, err507);
         }
 
         if (default_msg == NULL)
-                default_msg = "500 Internal Server Error";
+                default_msg = err500;
 
         return stop0(mfd, default_msg, strlen(default_msg));
 }
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..6ef3207 100644
--- a/mgmt.c
+++ b/mgmt.c
@@ -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/probes.d b/probes.d
index d6197d6..8b967c3 100644
--- a/probes.d
+++ b/probes.d
@@ -7,29 +7,30 @@
  * 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_begin(int fd, bool pipelined);
+
+        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_client_close(int fd, size_t buf_len);
         probe http_req_end();
 
-        /* DWARF: mog_ioq_ready(.return) */
+        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_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..df6ab88 100644
--- a/tapset/all.stp
+++ b/tapset/all.stp
@@ -8,7 +8,6 @@
 global cmogstored_http_req_begin;
 global cmogstored_http_pipelined;
 global cmogstored_http_addr;
-global cmogstored_fd_by_tid;
 
 probe process("cmogstored").mark("http_accepted") {
         fd = $arg1;
@@ -24,20 +23,22 @@ probe process("cmogstored").mark("http_accepted") {
  * mog_ioq_ready..ioq_reschedule   = time waiting for others to finish IO
  * ioq_reschedule..mog_ioq_unblock = time inside epoll ready list
  */
+probe process("cmogstored").mark("ioq_blocked") {
+        fd = $arg1;
+        printf("% 6d % 6d ioq blocked\n", pid(), fd);
+}
 
-/* 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 = user_string($arg2);
+        path = user_string($arg3);
+        printf("% 6d % 6d %s %s HTTP/1.1\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;
+        code = user_string_n($arg2, 3);
+        printf("% 6d % 6d HTTP res=%s\n", pid(), fd, code);
 }
 
 /*
@@ -45,85 +46,70 @@ probe process("cmogstored").function("mog_ioq_ready").return {
  * we will hit mog_ioq_unblock eventually
  */
 probe process("cmogstored").mark("ioq_reschedule") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
+        fd = $arg1;
         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;
-}
-
 /*
- * 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 reschedule_done\n", pid(), fd);
 }
 
 /*
  * HTTP client disconnected
  */
-probe process("cmogstored").function("http_close") {
-        fd = @cast($mfd, "struct mog_fd")->fd;
+probe process("cmogstored").mark("http_client_close") {
+        fd = $arg1;
         printf("% 6d % 6d closing\n", pid(), fd);
-        delete cmogstored_http_addr[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;
+        fd = $arg1;
+        is_pipelined = $arg2;
         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");
-}
-
-/*
  * 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 blocked with %lu bytes to write\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);
 }
diff --git a/thrpool.c b/thrpool.c
index 8ed5963..929b13f 100644
--- a/thrpool.c
+++ b/thrpool.c
@@ -132,7 +132,7 @@ thrpool_add(struct mog_thrpool *tp, unsigned size, unsigned long *nr_eagain)
 
         CHECK(int, 0, pthread_attr_init(&attr));
 
-        if (stacksize > 0)
+        if (stacksize > 0 && 0)
                 CHECK(int, 0, pthread_attr_setstacksize(&attr, stacksize));
 
         thr = &tp->threads[tp->n_threads].thr;
diff --git a/trywrite.c b/trywrite.c
index 7078748..b1374ff 100644
--- a/trywrite.c
+++ b/trywrite.c
@@ -93,7 +93,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;
                 }
@@ -150,7 +150,8 @@ void * mog_trysend(int fd, void *buf, size_t len, off_t more)
                         if (w < 0) {
                                 switch (errno) {
                                 case_EAGAIN:
-                                        TRACE(CMOGSTORED_WRITE_BUFFERED());
+                                        TRACE(CMOGSTORED_WRITE_BUFFERED(
+                                              fd, len));
                                         return wbuf_new(buf, len);
                                 case EINTR: continue;
                                 }