Re #1527: added debugging facility to the timer heap. By enabling PJ_TIMER_DEBUG, application can use pj_timer_heap_dump() or pjsip_endpt_dump() to dump the timer entries along with the source location where it is scheduled from. The macro will also enable dumping the timer heap entries when the SIP endpoint is being destroyed

git-svn-id: http://svn.pjsip.org/repos/pjproject/trunk@4154 74dad513-b988-da41-8d7b-12977e46ad98

9 files changed, 175 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
+
diff --git a/pjsip/include/pjsip/sip_endpoint.h b/pjsip/include/pjsip/sip_endpoint.h
index c6cf6d65..86dc9bef 100644
--- a/pjsip/include/pjsip/sip_endpoint.h
+++ b/pjsip/include/pjsip/sip_endpoint.h
@@ -150,9 +150,21 @@ PJ_DECL(pj_status_t) pjsip_endpt_handle_events2(pjsip_endpoint *endpt,
  * @param delay	    The relative delay of the timer.
  * @return	    PJ_OK (zero) if successfull.
  */
+#if PJ_TIMER_DEBUG
+#define pjsip_endpt_schedule_timer(ept,ent,d) \
+			pjsip_endpt_schedule_timer_dbg(ept, ent, d, \
+			                               __FILE__, __LINE__)
+
+PJ_DECL(pj_status_t) pjsip_endpt_schedule_timer_dbg(pjsip_endpoint *endpt,
+						    pj_timer_entry *entry,
+						    const pj_time_val *delay,
+						    const char *src_file,
+						    int src_line);
+#else
 PJ_DECL(pj_status_t) pjsip_endpt_schedule_timer( pjsip_endpoint *endpt,
 						 pj_timer_entry *entry,
 						 const pj_time_val *delay );
+#endif
 
 /**
  * Cancel the previously registered timer.
diff --git a/pjsip/include/pjsip/sip_event.h b/pjsip/include/pjsip/sip_event.h
index cd8a76fc..4e002bc1 100644
--- a/pjsip/include/pjsip/sip_event.h
+++ b/pjsip/include/pjsip/sip_event.h
@@ -34,6 +34,7 @@ PJ_BEGIN_DECL
  * @{
  */
 #include <pj/types.h>
+#include <pj/timer.h>
 
 
 /** 
diff --git a/pjsip/include/pjsua-lib/pjsua.h b/pjsip/include/pjsua-lib/pjsua.h
index 9de34cf3..02dc3f9b 100644
--- a/pjsip/include/pjsua-lib/pjsua.h
+++ b/pjsip/include/pjsua-lib/pjsua.h
@@ -2019,8 +2019,18 @@ PJ_DECL(pj_status_t) pjsua_verify_url(const char *url);
  *
  * @see pjsip_endpt_schedule_timer()
  */
+#if PJ_TIMER_DEBUG
+#define pjsua_schedule_timer(e,d) pjsua_schedule_timer_dbg(e,d,\
+                                                           __FILE__,__LINE__)
+
+PJ_DECL(pj_status_t) pjsua_schedule_timer_dbg(pj_timer_entry *entry,
+                                              const pj_time_val *delay,
+                                              const char *src_file,
+                                              int src_line);
+#else
 PJ_DECL(pj_status_t) pjsua_schedule_timer(pj_timer_entry *entry,
 					  const pj_time_val *delay);
+#endif
 
 /**
  * Schedule a callback function to be called after a specified time interval.
@@ -2033,9 +2043,20 @@ PJ_DECL(pj_status_t) pjsua_schedule_timer(pj_timer_entry *entry,
  *
  * @return		PJ_SUCCESS on success, or the appropriate error code.
  */
+#if PJ_TIMER_DEBUG
+#define pjsua_schedule_timer2(cb,u,d) \
+			pjsua_schedule_timer2_dbg(cb,u,d,__FILE__,__LINE__)
+
+PJ_DECL(pj_status_t) pjsua_schedule_timer2_dbg(void (*cb)(void *user_data),
+                                               void *user_data,
+                                               unsigned msec_delay,
+                                               const char *src_file,
+                                               int src_line);
+#else
 PJ_DECL(pj_status_t) pjsua_schedule_timer2(void (*cb)(void *user_data),
                                            void *user_data,
                                            unsigned msec_delay);
+#endif
 
 /**
  * Cancel the previously scheduled timer.
diff --git a/pjsip/src/pjsip/sip_endpoint.c b/pjsip/src/pjsip/sip_endpoint.c
index 3eb865b1..b1d7f7d2 100644
--- a/pjsip/src/pjsip/sip_endpoint.c
+++ b/pjsip/src/pjsip/sip_endpoint.c
@@ -606,6 +606,9 @@ PJ_DEF(void) pjsip_endpt_destroy(pjsip_endpoint *endpt)
     pj_ioqueue_destroy(endpt->ioqueue);
 
     /* Destroy timer heap */
+#if PJ_TIMER_DEBUG
+    pj_timer_heap_dump(endpt->timer_heap);
+#endif
     pj_timer_heap_destroy(endpt->timer_heap);
 
     /* Call all registered exit callbacks */
@@ -768,6 +771,19 @@ PJ_DEF(pj_status_t) pjsip_endpt_handle_events(pjsip_endpoint *endpt,
 /*
  * Schedule timer.
  */
+#if PJ_TIMER_DEBUG
+PJ_DEF(pj_status_t) pjsip_endpt_schedule_timer_dbg(pjsip_endpoint *endpt,
+						    pj_timer_entry *entry,
+						    const pj_time_val *delay,
+						    const char *src_file,
+						    int src_line)
+{
+    PJ_LOG(6, (THIS_FILE, "pjsip_endpt_schedule_timer(entry=%p, delay=%u.%u)",
+			 entry, delay->sec, delay->msec));
+    return pj_timer_heap_schedule_dbg(endpt->timer_heap, entry, delay,
+                                      src_file, src_line);
+}
+#else
 PJ_DEF(pj_status_t) pjsip_endpt_schedule_timer( pjsip_endpoint *endpt,
 						pj_timer_entry *entry,
 						const pj_time_val *delay )
@@ -776,6 +792,7 @@ PJ_DEF(pj_status_t) pjsip_endpt_schedule_timer( pjsip_endpoint *endpt,
 			 entry, delay->sec, delay->msec));
     return pj_timer_heap_schedule( endpt->timer_heap, entry, delay );
 }
+#endif
 
 /*
  * Cancel the previously registered timer.
@@ -1193,8 +1210,12 @@ PJ_DEF(void) pjsip_endpt_dump( pjsip_endpoint *endpt, pj_bool_t detail )
     pjsip_tpmgr_dump_transports( endpt->transport_mgr );
 
     /* Timer. */
+#if PJ_TIMER_DEBUG
+    pj_timer_heap_dump(endpt->timer_heap);
+#else
     PJ_LOG(3,(THIS_FILE, " Timer heap has %u entries", 
 			pj_timer_heap_count(endpt->timer_heap)));
+#endif
 
     /* Unlock mutex. */
     pj_mutex_unlock(endpt->mutex);
diff --git a/pjsip/src/pjsua-lib/pjsua_core.c b/pjsip/src/pjsua-lib/pjsua_core.c
index 1e4bc7ff..5c0ecc3b 100644
--- a/pjsip/src/pjsua-lib/pjsua_core.c
+++ b/pjsip/src/pjsua-lib/pjsua_core.c
@@ -2623,11 +2623,22 @@ PJ_DEF(pj_status_t) pjsua_verify_sip_url(const char *c_url)
 /*
  * Schedule a timer entry. 
  */
+#if PJ_TIMER_DEBUG
+PJ_DEF(pj_status_t) pjsua_schedule_timer_dbg( pj_timer_entry *entry,
+                                              const pj_time_val *delay,
+                                              const char *src_file,
+                                              int src_line)
+{
+    return pjsip_endpt_schedule_timer_dbg(pjsua_var.endpt, entry, delay,
+                                          src_file, src_line);
+}
+#else
 PJ_DEF(pj_status_t) pjsua_schedule_timer( pj_timer_entry *entry,
 					  const pj_time_val *delay)
 {
     return pjsip_endpt_schedule_timer(pjsua_var.endpt, entry, delay);
 }
+#endif
 
 /* Timer callback */
 static void timer_cb( pj_timer_heap_t *th,
@@ -2650,9 +2661,17 @@ static void timer_cb( pj_timer_heap_t *th,
 /*
  * Schedule a timer callback. 
  */
+#if PJ_TIMER_DEBUG
+PJ_DEF(pj_status_t) pjsua_schedule_timer2_dbg( void (*cb)(void *user_data),
+                                               void *user_data,
+                                               unsigned msec_delay,
+                                               const char *src_file,
+                                               int src_line)
+#else
 PJ_DEF(pj_status_t) pjsua_schedule_timer2( void (*cb)(void *user_data),
                                            void *user_data,
                                            unsigned msec_delay)
+#endif
 {
     pjsua_timer_list *tmr = NULL;
     pj_status_t status;
@@ -2672,7 +2691,12 @@ PJ_DEF(pj_status_t) pjsua_schedule_timer2( void (*cb)(void *user_data),
     delay.sec = 0;
     delay.msec = msec_delay;
 
+#if PJ_TIMER_DEBUG
+    status = pjsip_endpt_schedule_timer_dbg(pjsua_var.endpt, &tmr->entry,
+                                            &delay, src_file, src_line);
+#else
     status = pjsip_endpt_schedule_timer(pjsua_var.endpt, &tmr->entry, &delay);
+#endif
     if (status != PJ_SUCCESS) {
         pj_list_push_back(&pjsua_var.timer_list, tmr);
     }