Changeset 4154

Timestamp:

Jun 5, 2012 10:41:17 AM (12 years ago)

Author:

bennylp

Message:

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

Location:

pjproject/trunk

Files:

• pjlib/include/pj/config.h (modified) (1 diff)
• pjlib/include/pj/timer.h (modified) (4 diffs)
• pjlib/include/pj/types.h (modified) (1 diff)
• pjlib/src/pj/timer.c (modified) (4 diffs)
• pjsip/include/pjsip/sip_endpoint.h (modified) (1 diff)
• pjsip/include/pjsip/sip_event.h (modified) (1 diff)
• pjsip/include/pjsua-lib/pjsua.h (modified) (2 diffs)
• pjsip/src/pjsip/sip_endpoint.c (modified) (4 diffs)
• pjsip/src/pjsua-lib/pjsua_core.c (modified) (4 diffs)

pjproject/trunk/pjlib/include/pj/config.h

@@ -472 +472 @@
 #ifndef PJ_POOL_DEBUG
 #  define PJ_POOL_DEBUG             0
+#endif
+
+
+/**
+ * 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
 

pjproject/trunk/pjlib/include/pj/timer.h

@@ -86 +86 @@
  * This structure represents an entry to the timer.
  */
-struct pj_timer_entry
+typedef struct pj_timer_entry
 {
     /** 
@@ -118 +118 @@
      */
     pj_time_val _timer_value;
-};
+
+#if PJ_TIMER_DEBUG
+    const char  *src_file;
+    int          src_line;
+#endif
+} pj_timer_entry;
 
 
@@ -209 +214 @@
  * @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 */
 
 /**
@@ -263 +279 @@
                                       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
+
 /**
  * @}

pjproject/trunk/pjlib/include/pj/types.h

@@ -214 +214 @@
 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.

pjproject/trunk/pjlib/src/pj/timer.c

@@ -35 +35 @@
 #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))
@@ -453 +456 @@
 }
 
+#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;
@@ -466 +477 @@
     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);
@@ -553 +568 @@
 }
 
+#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
+

pjproject/trunk/pjsip/include/pjsip/sip_endpoint.h

@@ -151 +151 @@
  * @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
 
 /**

pjproject/trunk/pjsip/include/pjsip/sip_event.h

@@ -35 +35 @@
  */
 #include <pj/types.h>
+#include <pj/timer.h>
 
 

pjproject/trunk/pjsip/include/pjsua-lib/pjsua.h

@@ -2020 +2020 @@
  * @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
 
 /**
@@ -2034 +2044 @@
  * @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
 
 /**

pjproject/trunk/pjsip/src/pjsip/sip_endpoint.c

@@ -607 +607 @@
 
     /* Destroy timer heap */
+#if PJ_TIMER_DEBUG
+    pj_timer_heap_dump(endpt->timer_heap);
+#endif
     pj_timer_heap_destroy(endpt->timer_heap);
 
@@ -769 +772 @@
  * 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,
@@ -777 +793 @@
     return pj_timer_heap_schedule( endpt->timer_heap, entry, delay );
 }
+#endif
 
 /*
@@ -1194 +1211 @@
 
     /* 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. */

pjproject/trunk/pjsip/src/pjsua-lib/pjsua_core.c

@@ -2624 +2624 @@
  * 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)
@@ -2629 +2639 @@
     return pjsip_endpt_schedule_timer(pjsua_var.endpt, entry, delay);
 }
+#endif
 
 /* Timer callback */
@@ -2651 +2662 @@
  * 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;
@@ -2673 +2692 @@
     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);