Fix missing edge, add tracing

4 files changed, 41 insertions, 6 deletions

diff --git a/src/core/lib/iomgr/ev_epoll1_linux.c b/src/core/lib/iomgr/ev_epoll1_linux.c
index 8aa69cd73a..d31eafc70b 100644
--- a/src/core/lib/iomgr/ev_epoll1_linux.c
+++ b/src/core/lib/iomgr/ev_epoll1_linux.c
@@ -57,7 +57,6 @@
 #include "src/core/lib/iomgr/ev_posix.h"
 #include "src/core/lib/iomgr/iomgr_internal.h"
 #include "src/core/lib/iomgr/lockfree_event.h"
-#include "src/core/lib/iomgr/timer.h"
 #include "src/core/lib/iomgr/wakeup_fd_posix.h"
 #include "src/core/lib/iomgr/workqueue.h"
 #include "src/core/lib/profiling/timers.h"
diff --git a/src/core/lib/iomgr/ev_epollex_linux.c b/src/core/lib/iomgr/ev_epollex_linux.c
index 5a7c0448b6..cb6814e89e 100644
--- a/src/core/lib/iomgr/ev_epollex_linux.c
+++ b/src/core/lib/iomgr/ev_epollex_linux.c
@@ -582,6 +582,10 @@ static grpc_error *pollable_add_fd(pollable *p, grpc_fd *fd) {
   const int epfd = p->epfd;
   GPR_ASSERT(epfd != -1);
 
+  if (GRPC_TRACER_ON(grpc_polling_trace)) {
+    gpr_log(GPR_DEBUG, "add fd %p to pollable %p", fd, p);
+  }
+
   gpr_mu_lock(&fd->orphaned_mu);
   if (fd->orphaned) {
     gpr_mu_unlock(&fd->orphaned_mu);
@@ -961,7 +965,8 @@ static bool begin_worker(grpc_pollset *pollset, grpc_pollset_worker *worker,
     if (worker->pollable != &pollset->pollable) {
       gpr_mu_unlock(&pollset->pollable.po.mu);
     }
-    if (GRPC_TRACER_ON(grpc_polling_trace) && worker->pollable->root_worker != worker) {
+    if (GRPC_TRACER_ON(grpc_polling_trace) &&
+        worker->pollable->root_worker != worker) {
       gpr_log(GPR_DEBUG, "PS:%p wait %p w=%p for %dms", pollset,
               worker->pollable, worker,
               poll_deadline_to_millis_timeout(deadline, *now));
@@ -1080,6 +1085,10 @@ 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))
+      gpr_log(GPR_DEBUG,
+              "PS:%p add fd %p; transition pollable from empty to fd", pollset,
+              fd);
     /* empty pollable --> single fd pollable */
     append_error(&error, pollset_kick_all(pollset), err_desc);
     pollset->current_pollable = &fd->pollable;
@@ -1088,10 +1097,17 @@ 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))
+      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))
+      gpr_log(GPR_DEBUG,
+              "PS:%p add fd %p; transition pollable from fd %p to multipoller",
+              pollset, fd, had_fd);
+    append_error(&error, pollset_kick_all(pollset), err_desc);
     pollset->current_pollable = &pollset->pollable;
     if (append_error(&error, pollable_materialize(&pollset->pollable),
                      err_desc)) {
@@ -1458,7 +1474,8 @@ static const grpc_event_engine_vtable vtable = {
     .shutdown_engine = shutdown_engine,
 };
 
-const grpc_event_engine_vtable *grpc_init_epollex_linux(bool explicitly_requested) {
+const grpc_event_engine_vtable *grpc_init_epollex_linux(
+    bool explicitly_requested) {
   if (!grpc_has_wakeup_fd()) {
     return NULL;
   }
@@ -1483,7 +1500,10 @@ const grpc_event_engine_vtable *grpc_init_epollex_linux(bool explicitly_requeste
 #include "src/core/lib/iomgr/ev_posix.h"
 /* If GRPC_LINUX_EPOLL is not defined, it means epoll is not available. Return
  * NULL */
-const grpc_event_engine_vtable *grpc_init_epollex_linux(bool explicitly_requested) { return NULL; }
+const grpc_event_engine_vtable *grpc_init_epollex_linux(
+    bool explicitly_requested) {
+  return NULL;
+}
 #endif /* defined(GRPC_POSIX_SOCKET) */
 
 #endif /* !defined(GRPC_LINUX_EPOLL) */
diff --git a/src/core/lib/iomgr/lockfree_event.c b/src/core/lib/iomgr/lockfree_event.c
index 17e3bbf727..898ec1cb1b 100644
--- a/src/core/lib/iomgr/lockfree_event.c
+++ b/src/core/lib/iomgr/lockfree_event.c
@@ -35,6 +35,10 @@
 
 #include <grpc/support/log.h>
 
+#include "src/core/lib/debug/trace.h"
+
+extern grpc_tracer_flag grpc_polling_trace;
+
 /* 'state' holds the to call when the fd is readable or writable respectively.
    It can contain one of the following values:
      CLOSURE_READY     : The fd has an I/O event of interest but there is no
@@ -93,6 +97,10 @@ void grpc_lfev_notify_on(grpc_exec_ctx *exec_ctx, gpr_atm *state,
                          grpc_closure *closure) {
   while (true) {
     gpr_atm curr = gpr_atm_no_barrier_load(state);
+    if (GRPC_TRACER_ON(grpc_polling_trace)) {
+      gpr_log(GPR_DEBUG, "lfev_notify_on: %p curr=%p closure=%p", state,
+              (void *)curr, closure);
+    }
     switch (curr) {
       case CLOSURE_NOT_READY: {
         /* CLOSURE_NOT_READY -> <closure>.
@@ -155,6 +163,10 @@ bool grpc_lfev_set_shutdown(grpc_exec_ctx *exec_ctx, gpr_atm *state,
 
   while (true) {
     gpr_atm curr = gpr_atm_no_barrier_load(state);
+    if (GRPC_TRACER_ON(grpc_polling_trace)) {
+      gpr_log(GPR_DEBUG, "lfev_set_shutdown: %p curr=%p err=%s", state,
+              (void *)curr, grpc_error_string(shutdown_err));
+    }
     switch (curr) {
       case CLOSURE_READY:
       case CLOSURE_NOT_READY:
@@ -200,6 +212,10 @@ void grpc_lfev_set_ready(grpc_exec_ctx *exec_ctx, gpr_atm *state) {
   while (true) {
     gpr_atm curr = gpr_atm_no_barrier_load(state);
 
+    if (GRPC_TRACER_ON(grpc_polling_trace)) {
+      gpr_log(GPR_DEBUG, "lfev_set_ready: %p curr=%p", state, (void *)curr);
+    }
+
     switch (curr) {
       case CLOSURE_READY: {
         /* Already ready. We are done here */
diff --git a/src/core/lib/iomgr/tcp_client_posix.c b/src/core/lib/iomgr/tcp_client_posix.c
index ed3fd94a98..5c7da999e0 100644
--- a/src/core/lib/iomgr/tcp_client_posix.c
+++ b/src/core/lib/iomgr/tcp_client_posix.c
@@ -331,8 +331,8 @@ static void tcp_client_connect_impl(grpc_exec_ctx *exec_ctx,
   ac->channel_args = grpc_channel_args_copy(channel_args);
 
   if (GRPC_TRACER_ON(grpc_tcp_trace)) {
-    gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: asynchronously connecting",
-            ac->addr_str);
+    gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: asynchronously connecting fd %p",
+            ac->addr_str, fdobj);
   }
 
   gpr_mu_lock(&ac->mu);