From 86ffd65c84956f5e274beb11b34d8ea0bfc9a4af Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Tue, 20 Jun 2017 00:16:54 +0000 Subject: Add logging, fix some bugs --- src/core/lib/iomgr/ev_epollex_linux.c | 46 ++++++++++++++++++++++++++++++----- src/core/lib/support/log_linux.c | 4 ++- 2 files changed, 43 insertions(+), 7 deletions(-) (limited to 'src') diff --git a/src/core/lib/iomgr/ev_epollex_linux.c b/src/core/lib/iomgr/ev_epollex_linux.c index 949f8a845d..c785aa7b80 100644 --- a/src/core/lib/iomgr/ev_epollex_linux.c +++ b/src/core/lib/iomgr/ev_epollex_linux.c @@ -103,6 +103,24 @@ typedef struct pollable { grpc_pollset_worker *root_worker; } pollable; +static const char *polling_obj_type_string(polling_obj_type t) { + switch (t) { + case PO_POLLING_GROUP: return "polling_group"; + case PO_POLLSET_SET: return "pollset_set"; + case PO_POLLSET: return "pollset"; + case PO_FD: return "fd"; + case PO_EMPTY_POLLABLE: return "empty_pollable"; + case PO_COUNT: return ""; + } + return ""; +} + +static char *pollable_desc(pollable *p) { + char *out; + gpr_asprintf(&out, "type=%s group=%p epfd=%d wakeup=%d", polling_obj_type_string(p->po.type), p->po.group, p->epfd, p->wakeup.read_fd); + return out; +} + static pollable g_empty_pollable; static void pollable_init(pollable *p, polling_obj_type type); @@ -466,7 +484,7 @@ static grpc_error *pollable_add_fd(pollable *p, grpc_fd *fd) { GPR_ASSERT(epfd != -1); if (GRPC_TRACER_ON(grpc_polling_trace)) { - gpr_log(GPR_DEBUG, "add fd %p to pollable %p", fd, p); + gpr_log(GPR_DEBUG, "add fd %p (%d) to pollable %p", fd, fd->fd, p); } gpr_mu_lock(&fd->orphaned_mu); @@ -531,10 +549,16 @@ static void do_kick_all(grpc_exec_ctx *exec_ctx, void *arg, if (worker->pollable != &pollset->pollable) { gpr_mu_lock(&worker->pollable->po.mu); } - if (worker->initialized_cv) { + if (worker->initialized_cv && worker != pollset->root_worker) { + if (GRPC_TRACER_ON(grpc_polling_trace)) { + gpr_log(GPR_DEBUG, "PS:%p kickall_via_cv %p (pollable %p vs %p)", pollset, worker, &pollset->pollable, worker->pollable); + } worker->kicked = true; gpr_cv_signal(&worker->cv); } else { + if (GRPC_TRACER_ON(grpc_polling_trace)) { + gpr_log(GPR_DEBUG, "PS:%p kickall_via_wakeup %p (pollable %p vs %p)", pollset, worker, &pollset->pollable, worker->pollable); + } append_error(&error, grpc_wakeup_fd_wakeup(&worker->pollable->wakeup), "pollset_shutdown"); } @@ -764,7 +788,9 @@ static grpc_error *pollset_epoll(grpc_exec_ctx *exec_ctx, grpc_pollset *pollset, int timeout = poll_deadline_to_millis_timeout(deadline, now); if (GRPC_TRACER_ON(grpc_polling_trace)) { - gpr_log(GPR_DEBUG, "PS:%p poll %p for %dms", pollset, p, timeout); + char *desc = pollable_desc(p); + gpr_log(GPR_DEBUG, "PS:%p poll %p[%s] for %dms", pollset, p, desc, timeout); + gpr_free(desc); } if (timeout != 0) { @@ -979,10 +1005,11 @@ static grpc_error *pollset_add_fd_locked(grpc_exec_ctx *exec_ctx, static const char *err_desc = "pollset_add_fd"; grpc_error *error = GRPC_ERROR_NONE; if (pollset->current_pollable == &g_empty_pollable) { - if (GRPC_TRACER_ON(grpc_polling_trace)) + if (GRPC_TRACER_ON(grpc_polling_trace)) { gpr_log(GPR_DEBUG, "PS:%p add fd %p; transition pollable from empty to fd", pollset, fd); + } /* empty pollable --> single fd pollable */ pollset_kick_all(exec_ctx, pollset); pollset->current_pollable = &fd->pollable; @@ -991,16 +1018,23 @@ static grpc_error *pollset_add_fd_locked(grpc_exec_ctx *exec_ctx, if (!fd_locked) gpr_mu_unlock(&fd->pollable.po.mu); REF_BY(fd, 2, "pollset_pollable"); } else if (pollset->current_pollable == &pollset->pollable) { - if (GRPC_TRACER_ON(grpc_polling_trace)) + if (GRPC_TRACER_ON(grpc_polling_trace)) { gpr_log(GPR_DEBUG, "PS:%p add fd %p; already multipolling", pollset, fd); + } append_error(&error, pollable_add_fd(pollset->current_pollable, fd), err_desc); } else if (pollset->current_pollable != &fd->pollable) { grpc_fd *had_fd = (grpc_fd *)pollset->current_pollable; - if (GRPC_TRACER_ON(grpc_polling_trace)) + if (GRPC_TRACER_ON(grpc_polling_trace)) { gpr_log(GPR_DEBUG, "PS:%p add fd %p; transition pollable from fd %p to multipoller", pollset, fd, had_fd); + } + /* Introduce a spurious completion. + If we do not, then it may be that the fd-specific epoll set consumed + a completion without being polled, leading to a missed edge going up. */ + grpc_lfev_set_ready(exec_ctx, &had_fd->read_closure); + grpc_lfev_set_ready(exec_ctx, &had_fd->write_closure); pollset_kick_all(exec_ctx, pollset); pollset->current_pollable = &pollset->pollable; if (append_error(&error, pollable_materialize(&pollset->pollable), diff --git a/src/core/lib/support/log_linux.c b/src/core/lib/support/log_linux.c index 5c512661a3..61d2346427 100644 --- a/src/core/lib/support/log_linux.c +++ b/src/core/lib/support/log_linux.c @@ -64,6 +64,8 @@ void gpr_default_log(gpr_log_func_args *args) { time_t timer; gpr_timespec now = gpr_now(GPR_CLOCK_REALTIME); struct tm tm; + static __thread long tid = 0; + if (tid == 0) tid = gettid(); timer = (time_t)now.tv_sec; final_slash = strrchr(args->file, '/'); @@ -81,7 +83,7 @@ void gpr_default_log(gpr_log_func_args *args) { gpr_asprintf(&prefix, "%s%s.%09" PRId32 " %7ld %s:%d]", gpr_log_severity_string(args->severity), time_buffer, - now.tv_nsec, gettid(), display_file, args->line); + now.tv_nsec, tid, display_file, args->line); fprintf(stderr, "%-60s %s\n", prefix, args->message); gpr_free(prefix); -- cgit v1.2.3