From 1aef50d0091d1e710648ccade913ea80238520d9 Mon Sep 17 00:00:00 2001 From: Eric Wong Date: Fri, 26 Jul 2013 05:59:18 +0000 Subject: more probes WIP --- http.c | 13 +++++--- http_dav.c | 9 ++++++ http_get.c | 3 ++ http_put.c | 7 +++-- ioq.c | 2 ++ mgmt.c | 10 ++++-- probes.d | 31 ++++++++++--------- tapset/all.stp | 96 +++++++++++++++++++++++++--------------------------------- thrpool.c | 2 +- trywrite.c | 5 +-- 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,8 +57,15 @@ 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 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; } -- cgit v1.2.3-24-ge0c7