From f80c52cfe4e08fba39995830a3fcf5835d0bb846 Mon Sep 17 00:00:00 2001 From: Eric Wong Date: Mon, 6 May 2013 22:20:05 +0000 Subject: 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 *". --- .gitignore | 1 + Makefile.am | 14 ++++++++++- cmogstored.h | 8 +++---- configure.ac | 2 ++ http.c | 62 ++++++++++++++++++++++++++++++++++++++----------- http_dav.c | 10 ++++---- http_get.c | 3 ++- http_put.c | 5 ++-- m4/systemtap.m4 | 37 +++++++++++++++++++++++++++++ mgmt.c | 21 +++++++++++++++++ probes.d | 24 +++++++++++++++++++ tapset/http_request.stp | 40 +++++++++++++++++++++++++++++++ trace.h | 8 +++++++ trywrite.c | 19 +++++++++------ 14 files changed, 221 insertions(+), 33 deletions(-) create mode 100644 m4/systemtap.m4 create mode 100644 probes.d create mode 100644 tapset/http_request.stp create mode 100644 trace.h 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 + 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; -- cgit v1.2.3-24-ge0c7