fd refcount debugging

4 files changed, 73 insertions, 27 deletions

diff --git a/src/core/iomgr/fd_posix.c b/src/core/iomgr/fd_posix.c
index 5a7180a76b..65dff84a68 100644
--- a/src/core/iomgr/fd_posix.c
+++ b/src/core/iomgr/fd_posix.c
@@ -109,12 +109,28 @@ static void destroy(grpc_fd *fd) {
   gpr_free(fd);
 }
 
+#ifdef GRPC_FD_REF_COUNT_DEBUG
+#define REF_BY(fd, n, reason) ref_by(fd, n, reason, __FILE__, __LINE__)
+#define UNREF_BY(fd, n, reason) unref_by(fd, n, reason, __FILE__, __LINE__)
+static void ref_by(grpc_fd *fd, int n, const char *reason, const char *file, int line) {
+  gpr_log(GPR_DEBUG, "FD %d   ref %d %d -> %d [%s; %s:%d]", fd->fd, n, fd->refst, fd->refst + n, reason, file, line);
+#else
+#define REF_BY(fd, n, reason) ref_by(fd, n)
+#define UNREF_BY(fd, n, reason) unref_by(fd, n)
 static void ref_by(grpc_fd *fd, int n) {
+#endif
   GPR_ASSERT(gpr_atm_no_barrier_fetch_add(&fd->refst, n) > 0);
 }
 
+#ifdef GRPC_FD_REF_COUNT_DEBUG
+static void unref_by(grpc_fd *fd, int n, const char *reason, const char *file, int line) {
+  gpr_atm old;
+  gpr_log(GPR_DEBUG, "FD %d unref %d %d -> %d [%s; %s:%d]", fd->fd, n, fd->refst, fd->refst - n, reason, file, line);
+#else
 static void unref_by(grpc_fd *fd, int n) {
-  gpr_atm old = gpr_atm_full_fetch_add(&fd->refst, -n);
+  gpr_atm old;
+#endif
+  old = gpr_atm_full_fetch_add(&fd->refst, -n);
   if (old == n) {
     close(fd->fd);
     grpc_iomgr_add_callback(fd->on_done, fd->on_done_user_data);
@@ -182,17 +198,31 @@ void grpc_fd_orphan(grpc_fd *fd, grpc_iomgr_cb_func on_done, void *user_data) {
   fd->on_done = on_done ? on_done : do_nothing;
   fd->on_done_user_data = user_data;
   shutdown(fd->fd, SHUT_RDWR);
-  ref_by(fd, 1); /* remove active status, but keep referenced */
+  REF_BY(fd, 1, "orphan"); /* remove active status, but keep referenced */
   gpr_mu_lock(&fd->watcher_mu);
   wake_all_watchers_locked(fd);
   gpr_mu_unlock(&fd->watcher_mu);
-  unref_by(fd, 2); /* drop the reference */
+  UNREF_BY(fd, 2, "orphan"); /* drop the reference */
 }
 
 /* increment refcount by two to avoid changing the orphan bit */
-void grpc_fd_ref(grpc_fd *fd) { ref_by(fd, 2); }
+#ifdef GRPC_FD_REF_COUNT_DEBUG
+void grpc_fd_ref(grpc_fd *fd, const char *reason, const char *file, int line) { 
+  ref_by(fd, 2, reason, file, line); 
+}
+
+void grpc_fd_unref(grpc_fd *fd, const char *reason, const char *file, int line) { 
+  unref_by(fd, 2, reason, file, line); 
+}
+#else
+void grpc_fd_ref(grpc_fd *fd) { 
+  ref_by(fd, 2); 
+}
 
-void grpc_fd_unref(grpc_fd *fd) { unref_by(fd, 2); }
+void grpc_fd_unref(grpc_fd *fd) { 
+  unref_by(fd, 2); 
+}
+#endif
 
 static void make_callback(grpc_iomgr_cb_func cb, void *arg, int success,
                           int allow_synchronous_callback) {
@@ -316,7 +346,7 @@ gpr_uint32 grpc_fd_begin_poll(grpc_fd *fd, grpc_pollset *pollset,
   gpr_uint32 mask = 0;
   /* keep track of pollers that have requested our events, in case they change
    */
-  grpc_fd_ref(fd);
+  GRPC_FD_REF(fd, "poll");
 
   gpr_mu_lock(&fd->watcher_mu);
   /* if there is nobody polling for read, but we need to, then start doing so */
@@ -371,7 +401,7 @@ void grpc_fd_end_poll(grpc_fd_watcher *watcher, int got_read, int got_write) {
   }
   gpr_mu_unlock(&fd->watcher_mu);
 
-  grpc_fd_unref(fd);
+  GRPC_FD_UNREF(fd, "poll");
 }
 
 void grpc_fd_become_readable(grpc_fd *fd, int allow_synchronous_callback) {
diff --git a/src/core/iomgr/fd_posix.h b/src/core/iomgr/fd_posix.h
index cfc533b7f5..eb3c959cc1 100644
--- a/src/core/iomgr/fd_posix.h
+++ b/src/core/iomgr/fd_posix.h
@@ -161,8 +161,19 @@ void grpc_fd_become_readable(grpc_fd *fd, int allow_synchronous_callback);
 void grpc_fd_become_writable(grpc_fd *fd, int allow_synchronous_callback);
 
 /* Reference counting for fds */
+#define GRPC_FD_REF_COUNT_DEBUG
+
+#ifdef GRPC_FD_REF_COUNT_DEBUG
+void grpc_fd_ref(grpc_fd *fd, const char *reason, const char *file, int line);
+void grpc_fd_unref(grpc_fd *fd, const char *reason, const char *file, int line);
+#define GRPC_FD_REF(fd, reason) grpc_fd_ref(fd, reason, __FILE__, __LINE__)
+#define GRPC_FD_UNREF(fd, reason) grpc_fd_unref(fd, reason, __FILE__, __LINE__)
+#else
 void grpc_fd_ref(grpc_fd *fd);
 void grpc_fd_unref(grpc_fd *fd);
+#define GRPC_FD_REF(fd, reason) grpc_fd_ref(fd)
+#define GRPC_FD_UNREF(fd, reason) grpc_fd_unref(fd)
+#endif
 
 void grpc_fd_global_init(void);
 void grpc_fd_global_shutdown(void);
diff --git a/src/core/iomgr/pollset_multipoller_with_poll_posix.c b/src/core/iomgr/pollset_multipoller_with_poll_posix.c
index 9f137e48cd..7f7d851148 100644
--- a/src/core/iomgr/pollset_multipoller_with_poll_posix.c
+++ b/src/core/iomgr/pollset_multipoller_with_poll_posix.c
@@ -78,7 +78,7 @@ static void multipoll_with_poll_pollset_add_fd(grpc_pollset *pollset,
     h->fds = gpr_realloc(h->fds, sizeof(grpc_fd *) * h->fd_capacity);
   }
   h->fds[h->fd_count++] = fd;
-  grpc_fd_ref(fd);
+  GRPC_FD_REF(fd, "multipoller");
 }
 
 static void multipoll_with_poll_pollset_del_fd(grpc_pollset *pollset,
@@ -90,7 +90,7 @@ static void multipoll_with_poll_pollset_del_fd(grpc_pollset *pollset,
     h->dels = gpr_realloc(h->dels, sizeof(grpc_fd *) * h->del_capacity);
   }
   h->dels[h->del_count++] = fd;
-  grpc_fd_ref(fd);
+  GRPC_FD_REF(fd, "multipoller_del");
 }
 
 static void end_polling(grpc_pollset *pollset) {
@@ -144,7 +144,7 @@ static int multipoll_with_poll_pollset_maybe_work(
       if (h->fds[i] == h->dels[nd]) remove = 1;
     }
     if (remove) {
-      grpc_fd_unref(h->fds[i]);
+      GRPC_FD_UNREF(h->fds[i], "multipoller");
     } else {
       h->fds[nf++] = h->fds[i];
       h->watchers[np].fd = h->fds[i];
@@ -156,7 +156,7 @@ static int multipoll_with_poll_pollset_maybe_work(
   h->pfd_count = np;
   h->fd_count = nf;
   for (nd = 0; nd < h->del_count; nd++) {
-    grpc_fd_unref(h->dels[nd]);
+    GRPC_FD_UNREF(h->dels[nd], "multipoller_del");
   }
   h->del_count = 0;
   if (h->pfd_count == 0) {
@@ -198,6 +198,7 @@ static int multipoll_with_poll_pollset_maybe_work(
 
   gpr_mu_lock(&pollset->mu);
   pollset->counter--;
+
   return 1;
 }
 
@@ -210,10 +211,10 @@ static void multipoll_with_poll_pollset_destroy(grpc_pollset *pollset) {
   pollset_hdr *h = pollset->data.ptr;
   GPR_ASSERT(pollset->counter == 0);
   for (i = 0; i < h->fd_count; i++) {
-    grpc_fd_unref(h->fds[i]);
+    GRPC_FD_UNREF(h->fds[i], "multipoller");
   }
   for (i = 0; i < h->del_count; i++) {
-    grpc_fd_unref(h->dels[i]);
+    GRPC_FD_UNREF(h->dels[i], "multipoller_del");
   }
   gpr_free(h->pfds);
   gpr_free(h->watchers);
@@ -245,7 +246,7 @@ void grpc_poll_become_multipoller(grpc_pollset *pollset, grpc_fd **fds,
   h->dels = NULL;
   for (i = 0; i < nfds; i++) {
     h->fds[i] = fds[i];
-    grpc_fd_ref(fds[i]);
+    GRPC_FD_REF(fds[i], "multipoller");
   }
 }
 
diff --git a/src/core/iomgr/pollset_posix.c b/src/core/iomgr/pollset_posix.c
index c9577aedff..9aa481831e 100644
--- a/src/core/iomgr/pollset_posix.c
+++ b/src/core/iomgr/pollset_posix.c
@@ -119,15 +119,19 @@ int grpc_pollset_work(grpc_pollset *pollset, gpr_timespec deadline) {
   gpr_timespec now = gpr_now();
   int r;
   if (gpr_time_cmp(now, deadline) > 0) {
+    gpr_log(GPR_DEBUG, "out of time %p", pollset);
     return 0;
   }
   if (grpc_maybe_call_delayed_callbacks(&pollset->mu, 1)) {
+    gpr_log(GPR_DEBUG, "delayed calls %p", pollset);
     return 1;
   }
   if (grpc_alarm_check(&pollset->mu, now, &deadline)) {
+    gpr_log(GPR_DEBUG, "alarms %p", pollset);
     return 1;
   }
   if (pollset->shutting_down) {
+    gpr_log(GPR_DEBUG, "shutting down %p counter=%d", pollset, pollset->counter);
     return 1;
   }
   gpr_tls_set(&g_current_thread_poller, (gpr_intptr)pollset);
@@ -238,15 +242,15 @@ static void basic_do_promote(void *args, int success) {
 
     if (fds[0] && !grpc_fd_is_orphaned(fds[0])) {
       grpc_platform_become_multipoller(pollset, fds, GPR_ARRAY_SIZE(fds));
-      grpc_fd_unref(fds[0]);
+      GRPC_FD_UNREF(fds[0], "basicpoll");
     } else {
       /* old fd is orphaned and we haven't cleaned it up until now, so remain a
        * unary poller */
       /* Note that it is possible that fds[1] is also orphaned at this point.
        * That's okay, we'll correct it at the next add or poll. */
-      if (fds[0]) grpc_fd_unref(fds[0]);
+      if (fds[0]) GRPC_FD_UNREF(fds[0], "basicpoll");
       pollset->data.ptr = fd;
-      grpc_fd_ref(fd);
+      GRPC_FD_REF(fd, "basicpoll");
     }
   }
 
@@ -257,7 +261,7 @@ static void basic_do_promote(void *args, int success) {
   }
 
   /* Matching ref in basic_pollset_add_fd */
-  grpc_fd_unref(fd);
+  GRPC_FD_UNREF(fd, "basicpoll_add");
 }
 
 static void basic_pollset_add_fd(grpc_pollset *pollset, grpc_fd *fd) {
@@ -275,23 +279,23 @@ static void basic_pollset_add_fd(grpc_pollset *pollset, grpc_fd *fd) {
 
     if (fds[0] == NULL) {
       pollset->data.ptr = fd;
-      grpc_fd_ref(fd);
+      GRPC_FD_REF(fd, "basicpoll");
     } else if (!grpc_fd_is_orphaned(fds[0])) {
       grpc_platform_become_multipoller(pollset, fds, GPR_ARRAY_SIZE(fds));
-      grpc_fd_unref(fds[0]);
+      GRPC_FD_UNREF(fds[0], "basicpoll");
     } else {
       /* old fd is orphaned and we haven't cleaned it up until now, so remain a
        * unary poller */
-      grpc_fd_unref(fds[0]);
+      GRPC_FD_UNREF(fds[0], "basicpoll");
       pollset->data.ptr = fd;
-      grpc_fd_ref(fd);
+      GRPC_FD_REF(fd, "basicpoll");
     }
     return;
   }
 
   /* Now we need to promote. This needs to happen when we're not polling. Since
    * this may be called from poll, the wait needs to happen asynchronously. */
-  grpc_fd_ref(fd);
+  GRPC_FD_REF(fd, "basicpoll_add");
   pollset->in_flight_cbs++;
   up_args = gpr_malloc(sizeof(*up_args));
   up_args->pollset = pollset;
@@ -305,7 +309,7 @@ static void basic_pollset_add_fd(grpc_pollset *pollset, grpc_fd *fd) {
 static void basic_pollset_del_fd(grpc_pollset *pollset, grpc_fd *fd) {
   GPR_ASSERT(fd);
   if (fd == pollset->data.ptr) {
-    grpc_fd_unref(pollset->data.ptr);
+    GRPC_FD_UNREF(pollset->data.ptr, "basicpoll");
     pollset->data.ptr = NULL;
   }
 }
@@ -327,7 +331,7 @@ static int basic_pollset_maybe_work(grpc_pollset *pollset,
   }
   fd = pollset->data.ptr;
   if (fd && grpc_fd_is_orphaned(fd)) {
-    grpc_fd_unref(fd);
+    GRPC_FD_UNREF(fd, "basicpoll");
     fd = pollset->data.ptr = NULL;
   }
   if (gpr_time_cmp(deadline, gpr_inf_future) == 0) {
@@ -399,7 +403,7 @@ static int basic_pollset_maybe_work(grpc_pollset *pollset,
 static void basic_pollset_destroy(grpc_pollset *pollset) {
   GPR_ASSERT(pollset->counter == 0);
   if (pollset->data.ptr) {
-    grpc_fd_unref(pollset->data.ptr);
+    GRPC_FD_UNREF(pollset->data.ptr, "basicpoll");
   }
 }
 
@@ -412,7 +416,7 @@ static void become_basic_pollset(grpc_pollset *pollset, grpc_fd *fd_or_null) {
   pollset->counter = 0;
   pollset->data.ptr = fd_or_null;
   if (fd_or_null) {
-    grpc_fd_ref(fd_or_null);
+    GRPC_FD_REF(fd_or_null, "basicpoll");
   }
 }