Add logging, fix some bugs

2 files changed, 43 insertions, 7 deletions

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 "<invalid:count>";
+  }
+  return "<invalid>";
+}
+
+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);