Merge pull request #15203 from sreecha/fd-trace

fd tracing support

doc/environment_variables.md

@@ -49,6 +49,9 @@ some configuration as environment variables that can be set.
   - connectivity_state - traces connectivity state changes to channels
   - channel_stack_builder - traces information about channel stacks being built
   - executor - traces grpc's internal thread pool ('the executor')
+  - fd_trace - traces fd create(), shutdown() and close() calls for channel fds.
+    Also traces epoll fd create()/close() calls in epollex polling engine
+    traces epoll-fd creation/close calls for epollex polling engine
   - glb - traces the grpclb load balancer
   - handshaker - traces handshaking state
   - http - traces state in the http2 transport engine

src/core/lib/iomgr/ev_epollex_linux.cc

@@ -447,9 +447,13 @@ static grpc_error* pollable_create(pollable_type type, pollable** p) {
   if (epfd == -1) {
     return GRPC_OS_ERROR(errno, "epoll_create1");
   }
+  GRPC_FD_TRACE("Pollable_create: created epfd: %d (type: %d)", epfd, type);
   *p = static_cast<pollable*>(gpr_malloc(sizeof(**p)));
   grpc_error* err = grpc_wakeup_fd_init(&(*p)->wakeup);
   if (err != GRPC_ERROR_NONE) {
+    GRPC_FD_TRACE(
+        "Pollable_create: closed epfd: %d (type: %d). wakeupfd_init error",
+        epfd, type);
     close(epfd);
     gpr_free(*p);
     *p = nullptr;
@@ -460,6 +464,9 @@ static grpc_error* pollable_create(pollable_type type, pollable** p) {
   ev.data.ptr = (void*)(1 | (intptr_t) & (*p)->wakeup);
   if (epoll_ctl(epfd, EPOLL_CTL_ADD, (*p)->wakeup.read_fd, &ev) != 0) {
     err = GRPC_OS_ERROR(errno, "epoll_ctl");
+    GRPC_FD_TRACE(
+        "Pollable_create: closed epfd: %d (type: %d). epoll_ctl error", epfd,
+        type);
     close(epfd);
     grpc_wakeup_fd_destroy(&(*p)->wakeup);
     gpr_free(*p);
@@ -506,6 +513,7 @@ static void pollable_unref(pollable* p, int line, const char* reason) {
   }
 #endif
   if (p != nullptr && gpr_unref(&p->refs)) {
+    GRPC_FD_TRACE("pollable_unref: Closing epfd: %d", p->epfd);
     close(p->epfd);
     grpc_wakeup_fd_destroy(&p->wakeup);
     gpr_free(p);

src/core/lib/iomgr/ev_posix.cc

@@ -40,6 +40,9 @@
 
 grpc_core::TraceFlag grpc_polling_trace(false,
                                         "polling"); /* Disabled by default */
+
+/* Traces fd create/close operations */
+grpc_core::TraceFlag grpc_fd_trace(false, "fd_trace");
 grpc_core::DebugOnlyTraceFlag grpc_trace_fd_refcount(false, "fd_refcount");
 grpc_core::DebugOnlyTraceFlag grpc_polling_api_trace(false, "polling_api");
 
@@ -192,6 +195,7 @@ void grpc_event_engine_shutdown(void) {
 
 grpc_fd* grpc_fd_create(int fd, const char* name) {
   GRPC_POLLING_API_TRACE("fd_create(%d, %s)", fd, name);
+  GRPC_FD_TRACE("fd_create(%d, %s)", fd, name);
   return g_event_engine->fd_create(fd, name);
 }
 
@@ -204,11 +208,14 @@ void grpc_fd_orphan(grpc_fd* fd, grpc_closure* on_done, int* release_fd,
   GRPC_POLLING_API_TRACE("fd_orphan(%d, %p, %p, %d, %s)",
                          grpc_fd_wrapped_fd(fd), on_done, release_fd,
                          already_closed, reason);
+  GRPC_FD_TRACE("grpc_fd_orphan, fd:%d closed", grpc_fd_wrapped_fd(fd));
+
   g_event_engine->fd_orphan(fd, on_done, release_fd, already_closed, reason);
 }
 
 void grpc_fd_shutdown(grpc_fd* fd, grpc_error* why) {
   GRPC_POLLING_API_TRACE("fd_shutdown(%d)", grpc_fd_wrapped_fd(fd));
+  GRPC_FD_TRACE("fd_shutdown(%d)", grpc_fd_wrapped_fd(fd));
   g_event_engine->fd_shutdown(fd, why);
 }
 

src/core/lib/iomgr/ev_posix.h

@@ -29,8 +29,14 @@
 #include "src/core/lib/iomgr/pollset_set.h"
 #include "src/core/lib/iomgr/wakeup_fd_posix.h"
 
+extern grpc_core::TraceFlag grpc_fd_trace;      /* Disabled by default */
 extern grpc_core::TraceFlag grpc_polling_trace; /* Disabled by default */
 
+#define GRPC_FD_TRACE(format, ...)                        \
+  if (grpc_fd_trace.enabled()) {                          \
+    gpr_log(GPR_INFO, "(fd-trace) " format, __VA_ARGS__); \
+  }
+
 typedef struct grpc_fd grpc_fd;
 
 typedef struct grpc_event_engine_vtable {