diff options
| -rw-r--r-- | http.c | 19 | ||||
| -rw-r--r-- | http_dav.c | 8 | ||||
| -rw-r--r-- | http_get.c | 10 | ||||
| -rw-r--r-- | http_put.c | 3 | ||||
| -rw-r--r-- | ioq.c | 2 | ||||
| -rw-r--r-- | mgmt.c | 16 | ||||
| -rw-r--r-- | mgmt.h | 6 | ||||
| -rw-r--r-- | mgmt_fn.c | 24 | ||||
| -rw-r--r-- | probes.d | 36 | ||||
| -rw-r--r-- | tapset/all.stp | 182 | ||||
| -rwxr-xr-x | tapset/http_access_log.gawk | 62 | ||||
| -rwxr-xr-x | tapset/ioq_wait.awk | 53 | ||||
| -rw-r--r-- | trywrite.c | 4 |
13 files changed, 311 insertions, 114 deletions
@@ -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); } @@ -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 @@ -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); @@ -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; @@ -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; } @@ -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; } @@ -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 *); @@ -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); } @@ -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 +} @@ -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); |