4 files changed, 96 insertions, 7 deletions

diff --git a/pjlib/include/pj/config.h b/pjlib/include/pj/config.h
index 61249bef..c221a042 100644
--- a/pjlib/include/pj/config.h
+++ b/pjlib/include/pj/config.h
@@ -475,6 +475,19 @@
 
 
 /**
+ * Enable timer heap debugging facility. When this is enabled, application
+ * can call pj_timer_heap_dump() to show the contents of the timer heap
+ * along with the source location where the timer entries were scheduled.
+ * See https://trac.pjsip.org/repos/ticket/1527 for more info.
+ *
+ * Default: 0
+ */
+#ifndef PJ_TIMER_DEBUG
+#  define PJ_TIMER_DEBUG	    0
+#endif
+
+
+/**
  * Specify this as \a stack_size argument in #pj_thread_create() to specify
  * that thread should use default stack size for the current platform.
  *
diff --git a/pjlib/include/pj/timer.h b/pjlib/include/pj/timer.h
index 24d2bcb5..c2182ce3 100644
--- a/pjlib/include/pj/timer.h
+++ b/pjlib/include/pj/timer.h
@@ -85,7 +85,7 @@ typedef void pj_timer_heap_callback(pj_timer_heap_t *timer_heap,
 /**
  * This structure represents an entry to the timer.
  */
-struct pj_timer_entry
+typedef struct pj_timer_entry
 {
     /** 
      * User data to be associated with this entry. 
@@ -117,7 +117,12 @@ struct pj_timer_entry
      * by timer heap when the timer is scheduled.
      */
     pj_time_val _timer_value;
-};
+
+#if PJ_TIMER_DEBUG
+    const char	*src_file;
+    int		 src_line;
+#endif
+} pj_timer_entry;
 
 
 /**
@@ -208,9 +213,20 @@ PJ_DECL(pj_timer_entry*) pj_timer_entry_init( pj_timer_entry *entry,
  * @param delay     The interval to expire.
  * @return          PJ_SUCCESS, or the appropriate error code.
  */
+#if PJ_TIMER_DEBUG
+#  define pj_timer_heap_schedule(ht,e,d) \
+			pj_timer_heap_schedule_dbg(ht,e,d,__FILE__,__LINE__)
+
+  PJ_DECL(pj_status_t) pj_timer_heap_schedule_dbg( pj_timer_heap_t *ht,
+        					   pj_timer_entry *entry,
+        					   const pj_time_val *delay,
+        					   const char *src_file,
+        					   int src_line);
+#else
 PJ_DECL(pj_status_t) pj_timer_heap_schedule( pj_timer_heap_t *ht,
 					     pj_timer_entry *entry, 
 					     const pj_time_val *delay);
+#endif	/* PJ_TIMER_DEBUG */
 
 /**
  * Cancel a previously registered timer.
@@ -262,6 +278,15 @@ PJ_DECL(pj_status_t) pj_timer_heap_earliest_time( pj_timer_heap_t *ht,
 PJ_DECL(unsigned) pj_timer_heap_poll( pj_timer_heap_t *ht, 
                                       pj_time_val *next_delay);
 
+#if PJ_TIMER_DEBUG
+/**
+ * Dump timer heap entries.
+ *
+ * @param ht	    The timer heap.
+ */
+PJ_DECL(void) pj_timer_heap_dump(pj_timer_heap_t *ht);
+#endif
+
 /**
  * @}
  */
diff --git a/pjlib/include/pj/types.h b/pjlib/include/pj/types.h
index 1e434dd3..9f05ce44 100644
--- a/pjlib/include/pj/types.h
+++ b/pjlib/include/pj/types.h
@@ -213,11 +213,6 @@ typedef struct pj_ioqueue_key_t pj_ioqueue_key_t;
  */
 typedef struct pj_timer_heap_t pj_timer_heap_t;
 
-/**
- * Forward declaration for timer entry.
- */
-typedef struct pj_timer_entry pj_timer_entry;
-
 /** 
  * Opaque data type for atomic operations.
  */
diff --git a/pjlib/src/pj/timer.c b/pjlib/src/pj/timer.c
index 573c7ecb..ad037068 100644
--- a/pjlib/src/pj/timer.c
+++ b/pjlib/src/pj/timer.c
@@ -34,6 +34,9 @@
 #include <pj/assert.h>
 #include <pj/errno.h>
 #include <pj/lock.h>
+#include <pj/log.h>
+
+#define THIS_FILE	"timer.c"
 
 #define HEAP_PARENT(X)	(X == 0 ? 0 : (((X) - 1) / 2))
 #define HEAP_LEFT(X)	(((X)+(X))+1)
@@ -452,9 +455,17 @@ PJ_DEF(pj_timer_entry*) pj_timer_entry_init( pj_timer_entry *entry,
     return entry;
 }
 
+#if PJ_TIMER_DEBUG
+PJ_DEF(pj_status_t) pj_timer_heap_schedule_dbg( pj_timer_heap_t *ht,
+						pj_timer_entry *entry,
+						const pj_time_val *delay,
+						const char *src_file,
+						int src_line)
+#else
 PJ_DEF(pj_status_t) pj_timer_heap_schedule( pj_timer_heap_t *ht,
 					    pj_timer_entry *entry, 
 					    const pj_time_val *delay)
+#endif
 {
     pj_status_t status;
     pj_time_val expires;
@@ -465,6 +476,10 @@ PJ_DEF(pj_status_t) pj_timer_heap_schedule( pj_timer_heap_t *ht,
     /* Prevent same entry from being scheduled more than once */
     PJ_ASSERT_RETURN(entry->_timer_id < 1, PJ_EINVALIDOP);
 
+#if PJ_TIMER_DEBUG
+    entry->src_file = src_file;
+    entry->src_line = src_line;
+#endif
     pj_gettickcount(&expires);
     PJ_TIME_VAL_ADD(expires, *delay);
     
@@ -552,3 +567,44 @@ PJ_DEF(pj_status_t) pj_timer_heap_earliest_time( pj_timer_heap_t * ht,
     return PJ_SUCCESS;
 }
 
+#if PJ_TIMER_DEBUG
+PJ_DEF(void) pj_timer_heap_dump(pj_timer_heap_t *ht)
+{
+    lock_timer_heap(ht);
+
+    PJ_LOG(3,(THIS_FILE, "Dumping timer heap:"));
+    PJ_LOG(3,(THIS_FILE, "  Cur size: %d entries, max: %d",
+			 (int)ht->cur_size, (int)ht->max_size));
+
+    if (ht->cur_size) {
+	unsigned i;
+	pj_time_val now;
+
+	PJ_LOG(3,(THIS_FILE, "  Entries: "));
+	PJ_LOG(3,(THIS_FILE, "    _id\tId\tElapsed\tSource"));
+	PJ_LOG(3,(THIS_FILE, "    ----------------------------------"));
+
+	pj_gettickcount(&now);
+
+	for (i=0; i<(unsigned)ht->cur_size; ++i) {
+	    pj_timer_entry *e = ht->heap[i];
+	    pj_time_val delta;
+
+	    if (PJ_TIME_VAL_LTE(e->_timer_value, now))
+		delta.sec = delta.msec = 0;
+	    else {
+		delta = e->_timer_value;
+		PJ_TIME_VAL_SUB(delta, now);
+	    }
+
+	    PJ_LOG(3,(THIS_FILE, "    %d\t%d\t%d.%03d\t%s:%d",
+		      e->_timer_id, e->id,
+		      (int)delta.sec, (int)delta.msec,
+		      e->src_file, e->src_line));
+	}
+    }
+
+    unlock_timer_heap(ht);
+}
+#endif
+