]> git.ipfire.org Git - thirdparty/tvheadend.git/commitdiff
added tprofile to gather code timings
authorJaroslav Kysela <perex@perex.cz>
Sun, 8 Apr 2018 09:47:24 +0000 (11:47 +0200)
committerJaroslav Kysela <perex@perex.cz>
Sun, 8 Apr 2018 09:49:32 +0000 (11:49 +0200)
Makefile
src/input/mpegts.h
src/input/mpegts/mpegts_input.c
src/input/mpegts/mpegts_table.c
src/main.c
src/tprofile.c [new file with mode: 0644]
src/tprofile.h [new file with mode: 0644]
src/tvheadend.h
src/tvhlog.c
src/tvhlog.h

index ac15d94234cc5f7ae260b2bb76ab6d68b9574111..c9667be172b7258aca1d870e08d4d519b1a96eb1 100644 (file)
--- a/Makefile
+++ b/Makefile
@@ -208,6 +208,7 @@ SRCS-1 = \
        src/uuid.c \
        src/main.c \
        src/tvhlog.c \
+       src/tprofile.c \
        src/idnode.c \
        src/prop.c \
        src/proplib.c \
index 777a9cfc942c1f37b2be5ddc6029c57a4bd70fff..6d88db94cf6bd25b0d863833a8674062d6f76d75 100644 (file)
@@ -25,6 +25,7 @@
 #endif
 
 #include "atomic.h"
+#include "tprofile.h"
 #include "sbuf.h"
 #include "input.h"
 #include "service.h"
@@ -269,6 +270,8 @@ struct mpegts_table
   struct mpegts_table_mux_cb *mt_mux_cb;
 
   mpegts_service_t *mt_service;
+
+  tprofile_t mt_profile;
   
   void (*mt_destroy) (mpegts_table_t *mt); // Allow customisable destroy hook
                                            // useful for dynamic allocation of
@@ -710,6 +713,7 @@ struct mpegts_input
   TAILQ_HEAD(,mpegts_packet)      mi_input_queue;
   uint64_t                        mi_input_queue_size;
   tvhlog_limit_t                  mi_input_queue_loglimit;
+  qprofile_t                      mi_qprofile;
   int                             mi_remove_scrambled_bits;
 
   /* Data processing/output */
index 5464dcb4347c0d4eb1fa5c6ff8ec2a8f4d16e653..b7bdf1d531993e89142494004455edc5f87c5575 100644 (file)
@@ -1,4 +1,4 @@
-/*
+  /*
  *  Tvheadend - MPEGTS input source
  *  Copyright (C) 2013 Adam Sutton
  *
@@ -1161,6 +1161,7 @@ mpegts_input_queue_packets
   ( mpegts_mux_instance_t *mmi, mpegts_packet_t *mp )
 {
   mpegts_input_t *mi = mmi->mmi_input;
+  const char *id = SRCLINEID();
   int len = mp->mp_len;
 
   pthread_mutex_lock(&mi->mi_input_lock);
@@ -1170,10 +1171,13 @@ mpegts_input_queue_packets
       memoryinfo_alloc(&mpegts_input_queue_memoryinfo, sizeof(mpegts_packet_t) + len);
       mpegts_mux_grab(mp->mp_mux);
       TAILQ_INSERT_TAIL(&mi->mi_input_queue, mp, mp_link);
+      tprofile_queue_add(&mi->mi_qprofile, id, len);
+      tprofile_queue_set(&mi->mi_qprofile, id, mi->mi_input_queue_size);
       tvh_cond_signal(&mi->mi_input_cond, 0);
     } else {
       if (tvhlog_limit(&mi->mi_input_queue_loglimit, 10))
         tvhwarn(LS_MPEGTS, "too much queued input data (over 50MB) for %s, discarding new", mi->mi_name);
+      tprofile_queue_drop(&mi->mi_qprofile, id, len);
       free(mp);
     }
   } else {
@@ -1301,6 +1305,7 @@ mpegts_input_table_dispatch
     if (mt->mt_destroyed || !mt->mt_subscribed || mt->mt_pid != pid)
       continue;
     mpegts_table_grab(mt);
+    tprofile_start(&mt->mt_profile, "dispatch");
     if (len < i)
       vec[len++] = mt;
   }
@@ -1318,6 +1323,7 @@ mpegts_input_table_dispatch
         mpegts_psi_section_reassemble((mpegts_psi_table_t *)mt, logprefix,
                                       tsb2, mt->mt_flags & MT_CRC,
                                       mpegts_table_dispatch, mt);
+    tprofile_finish(&mt->mt_profile);
     mpegts_table_release(mt);
   }
 }
@@ -1644,14 +1650,18 @@ static void *
 mpegts_input_thread ( void * p )
 {
   mpegts_packet_t *mp;
-  mpegts_input_t  *mi = p;
+  mpegts_input_t *mi = p;
   size_t bytes = 0;
   int update_pids;
+  tprofile_t tprofile;
   char buf[256];
 
   pthread_mutex_lock(&global_lock);
   mi->mi_display_name(mi, buf, sizeof(buf));
   pthread_mutex_unlock(&global_lock);
+
+  tprofile_init(&tprofile, buf);
+
   pthread_mutex_lock(&mi->mi_input_lock);
   while (atomic_get(&mi->mi_running)) {
 
@@ -1679,7 +1689,9 @@ mpegts_input_thread ( void * p )
       pthread_mutex_unlock(&global_lock);
       pthread_mutex_lock(&mi->mi_output_lock);
     }
+    tprofile_start(&tprofile, "input");
     bytes += mpegts_input_process(mi, mp);
+    tprofile_finish(&tprofile);
     update_pids = mp->mp_mux && mp->mp_mux->mm_update_pids_flag;
     pthread_mutex_unlock(&mi->mi_output_lock);
     if (update_pids) {
@@ -1716,15 +1728,17 @@ mpegts_input_thread ( void * p )
   mi->mi_input_queue_size = 0;
   pthread_mutex_unlock(&mi->mi_input_lock);
 
+  tprofile_done(&tprofile);
+
   return NULL;
 }
 
 static void *
 mpegts_input_table_thread ( void *aux )
 {
-  mpegts_table_feed_t   *mtf;
-  mpegts_input_t        *mi = aux;
-  mpegts_mux_t          *mm = NULL;
+  mpegts_table_feed_t *mtf;
+  mpegts_input_t *mi = aux;
+  mpegts_mux_t *mm = NULL;
 
   pthread_mutex_lock(&mi->mi_output_lock);
   while (atomic_get(&mi->mi_running)) {
@@ -1984,12 +1998,16 @@ mpegts_input_create0
   ( mpegts_input_t *mi, const idclass_t *class, const char *uuid,
     htsmsg_t *c )
 {
+  char buf[32];
+
   if (idnode_insert(&mi->ti_id, uuid, class, 0)) {
     if (uuid)
       tvherror(LS_MPEGTS, "invalid input uuid '%s'", uuid);
     free(mi);
     return NULL;
   }
+  snprintf(buf, sizeof(buf), "input %p", mi);
+  tprofile_queue_init(&mi->mi_qprofile, buf);
   LIST_INSERT_HEAD(&tvh_inputs, (tvh_input_t*)mi, ti_link);
   
   /* Defaults */
@@ -2082,6 +2100,7 @@ mpegts_input_delete ( mpegts_input_t *mi, int delconf )
   /* Stop threads (will unlock global_lock to join) */
   mpegts_input_thread_stop(mi);
 
+  tprofile_queue_done(&mi->mi_qprofile);
   pthread_mutex_destroy(&mi->mi_output_lock);
   tvh_cond_destroy(&mi->mi_table_cond);
   free(mi->mi_name);
index 5f89450f33a0da902e79dbf8753cfa89b7f45292..df40748fb6821443f1a0802bb446ebed75178832 100644 (file)
@@ -124,6 +124,7 @@ mpegts_table_release_ ( mpegts_table_t *mt )
   if (mt->mt_destroy)
     mt->mt_destroy(mt);
   free(mt->mt_name);
+  tprofile_done(&mt->mt_profile);
   if (tvhtrace_enabled()) {
     /* poison */
     memset(mt, 0xa5, sizeof(*mt));
@@ -207,6 +208,7 @@ mpegts_table_add
 {
   mpegts_table_t *mt;
   int subscribe = 1;
+  char buf[64];
 
   /* Check for existing */
   pthread_mutex_lock(&mm->mm_tables_lock);
@@ -258,6 +260,8 @@ mpegts_table_add
   mt->mt_sect.ps_cc = -1;
   mt->mt_sect.ps_table = tableid;
   mt->mt_sect.ps_mask = mask;
+  snprintf(buf, sizeof(buf), "%s %p", mt->mt_name, mt);
+  tprofile_init(&mt->mt_profile, buf);
 
   /* Open table */
   if (pid < 0) {
index 2cb16a190bb502a68f4885c29ad3a44d918f6e95..47a00fa0dad8c772d6db270d9050cdde288a49ed 100644 (file)
@@ -76,6 +76,7 @@
 #include "streaming.h"
 #include "memoryinfo.h"
 #include "watchdog.h"
+#include "tprofile.h"
 #if CONFIG_LINUXDVB_CA
 #include "input/mpegts/en50221/en50221.h"
 #endif
@@ -190,8 +191,10 @@ static tvh_cond_t mtimer_cond;
 static int64_t mtimer_periodic;
 static pthread_t mtimer_tid;
 static pthread_t mtimer_tick_tid;
+static tprofile_t mtimer_profile;
 static LIST_HEAD(, gtimer) gtimers;
 static pthread_cond_t gtimer_cond;
+static tprofile_t gtimer_profile;
 static TAILQ_HEAD(, tasklet) tasklets;
 static tvh_cond_t tasklet_cond;
 static pthread_t tasklet_tid;
@@ -271,7 +274,6 @@ GTIMER_FCN(mtimer_arm_abs)
   mti->mti_expire   = when;
 #if ENABLE_GTIMER_CHECK
   mti->mti_id       = id;
-  mti->mti_fcn      = fcn;
 #endif
 
   LIST_INSERT_SORTED(&mtimers, mti, mti_link, mtimercmp);
@@ -288,7 +290,7 @@ GTIMER_FCN(mtimer_arm_rel)
   (GTIMER_TRACEID_ mtimer_t *gti, mti_callback_t *callback, void *opaque, int64_t delta)
 {
 #if ENABLE_GTIMER_CHECK
-  GTIMER_FCN(mtimer_arm_abs)(id, fcn, gti, callback, opaque, mclk() + delta);
+  GTIMER_FCN(mtimer_arm_abs)(id, gti, callback, opaque, mclk() + delta);
 #else
   mtimer_arm_abs(gti, callback, opaque, mclk() + delta);
 #endif
@@ -332,7 +334,6 @@ GTIMER_FCN(gtimer_arm_absn)
   gti->gti_expire   = when;
 #if ENABLE_GTIMER_CHECK
   gti->gti_id       = id;
-  gti->gti_fcn      = fcn;
 #endif
 
   LIST_INSERT_SORTED(&gtimers, gti, gti_link, gtimercmp);
@@ -349,7 +350,7 @@ GTIMER_FCN(gtimer_arm_rel)
   (GTIMER_TRACEID_ gtimer_t *gti, gti_callback_t *callback, void *opaque, time_t delta)
 {
 #if ENABLE_GTIMER_CHECK
-  GTIMER_FCN(gtimer_arm_absn)(id, fcn, gti, callback, opaque, gclk() + delta);
+  GTIMER_FCN(gtimer_arm_absn)(id, gti, callback, opaque, gclk() + delta);
 #else
   gtimer_arm_absn(gti, callback, opaque, gclk() + delta);
 #endif
@@ -575,6 +576,7 @@ mdispatch_clock_update(void)
   if (mono > atomic_get_s64(&mtimer_periodic)) {
     atomic_set_s64(&mtimer_periodic, mono + MONOCLOCK_RESOLUTION);
     gdispatch_clock_update(); /* gclk() update */
+    tprofile_log_stats(); /* Log timings */
     comet_flush(); /* Flush idle comet mailboxes */
   }
 
@@ -605,11 +607,7 @@ mtimer_thread(void *aux)
   mtimer_t *mti;
   mti_callback_t *cb;
   int64_t now, next;
-#if ENABLE_GTIMER_CHECK
-  int64_t mtm;
   const char *id;
-  const char *fcn;
-#endif
 
   pthread_mutex_lock(&global_lock);
   while (tvheadend_is_running() && atomic_get(&tvheadend_mainloop) == 0)
@@ -632,10 +630,12 @@ mtimer_thread(void *aux)
       }
 
 #if ENABLE_GTIMER_CHECK
-      mtm = getmonoclock();
       id = mti->mti_id;
-      fcn = mti->mti_fcn;
+#else
+      id = NULL;
 #endif
+      tprofile_start(&mtimer_profile, id);
+
       cb = mti->mti_callback;
 
       LIST_REMOVE(mti, mti_link);
@@ -643,11 +643,7 @@ mtimer_thread(void *aux)
 
       cb(mti->mti_opaque);
 
-#if ENABLE_GTIMER_CHECK
-      mtm = getmonoclock() - mtm;
-      if (mtm > 10000)
-        tvhtrace(LS_MTIMER, "%s:%s duration %"PRId64"us", id, fcn, mtm);
-#endif
+      tprofile_finish(&mtimer_profile);
     }
 
     /* Periodic updates */
@@ -672,11 +668,7 @@ mainloop(void)
   gti_callback_t *cb;
   time_t now;
   struct timespec ts;
-#if ENABLE_GTIMER_CHECK
-  int64_t mtm;
   const char *id;
-  const char *fcn;
-#endif
 
   while (tvheadend_is_running()) {
     now = gdispatch_clock_update();
@@ -703,10 +695,12 @@ mainloop(void)
       }
 
 #if ENABLE_GTIMER_CHECK
-      mtm = getmonoclock();
       id = gti->gti_id;
-      fcn = gti->gti_fcn;
+#else
+      id = NULL;
 #endif
+      tprofile_start(&gtimer_profile, id);
+
       cb = gti->gti_callback;
 
       LIST_REMOVE(gti, gti_link);
@@ -714,11 +708,7 @@ mainloop(void)
 
       cb(gti->gti_opaque);
 
-#if ENABLE_GTIMER_CHECK
-      mtm = getmonoclock() - mtm;
-      if (mtm > 10000)
-        tvhtrace(LS_GTIMER, "%s:%s duration %"PRId64"us", id, fcn, mtm);
-#endif
+      tprofile_finish(&gtimer_profile);
     }
 
     /* Wait */
@@ -801,7 +791,8 @@ main(int argc, char **argv)
               opt_dbus_session = 0,
               opt_nobackup     = 0,
               opt_nobat        = 0,
-              opt_subsystems   = 0;
+              opt_subsystems   = 0,
+              opt_tprofile     = 0;
   const char *opt_config       = NULL,
              *opt_user         = NULL,
              *opt_group        = NULL,
@@ -910,6 +901,8 @@ main(int argc, char **argv)
     { 0, "tsfile", N_("tsfile input (mux file)"), OPT_STR_LIST, &opt_tsfile },
 #endif
 
+    { 0, "tprofile", N_("Gather timing statistics for the code"), OPT_BOOL, &opt_tprofile },
+
   };
 
   /* Get current directory */
@@ -1088,6 +1081,9 @@ main(int argc, char **argv)
     }
   }
 
+  tprofile_module_init(opt_tprofile);
+  tprofile_init(&gtimer_profile, "gtimer");
+  tprofile_init(&mtimer_profile, "mtimer");
   uuid_init();
   idnode_boot();
   config_boot(opt_config, gid, uid, opt_user_agent);
@@ -1360,6 +1356,9 @@ main(int argc, char **argv)
   tvhftrace(LS_MAIN, notify_done);
   tvhftrace(LS_MAIN, spawn_done);
 
+  tprofile_done(&gtimer_profile);
+  tprofile_done(&mtimer_profile);
+  tprofile_module_done();
   tvhlog(LOG_NOTICE, LS_STOP, "Exiting HTS Tvheadend");
   tvhlog_end();
 
diff --git a/src/tprofile.c b/src/tprofile.c
new file mode 100644 (file)
index 0000000..17568f2
--- /dev/null
@@ -0,0 +1,277 @@
+/*
+ *  tvheadend, Gather timing statistics - profiling
+ *  Copyright (C) 2018 Jaroslav Kysela
+ *
+ *  This program is free software: you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License as published by
+ *  the Free Software Foundation, either version 3 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU General Public License for more details.
+ *
+ *  You should have received a copy of the GNU General Public License
+ *  along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include <assert.h>
+#include "tvhlog.h"
+#include "clock.h"
+#include "tprofile.h"
+
+int tprofile_running;
+static pthread_mutex_t tprofile_mutex;
+static pthread_mutex_t qprofile_mutex;
+static LIST_HEAD(, tprofile) tprofile_all;
+static LIST_HEAD(, qprofile) qprofile_all;
+
+void tprofile_init1(tprofile_t *tprof, const char *name)
+{
+  memset(tprof, 0, sizeof(*tprof));
+  tprof->name = strdup(name);
+  pthread_mutex_lock(&tprofile_mutex);
+  LIST_INSERT_HEAD(&tprofile_all, tprof, link);
+  pthread_mutex_unlock(&tprofile_mutex);
+}
+
+static void tprofile_time_done(tprofile_time_t *tpt)
+{
+  free(tpt->id);
+}
+
+static void tprofile_avg_done(tprofile_avg_t *tpa)
+{
+}
+
+static void tprofile_destroy(tprofile_t *tprof)
+{
+  free(tprof->name);
+  free(tprof->start_id);
+  tprofile_time_done(&tprof->tmax);
+  tprofile_avg_done(&tprof->tavg);
+}
+
+void tprofile_done1(tprofile_t *tprof)
+{
+  tprofile_t *fin = malloc(sizeof(*fin));
+  pthread_mutex_lock(&tprofile_mutex);
+  LIST_REMOVE(tprof, link);
+  if (fin) {
+    *fin = *tprof;
+    fin->changed = fin->finish = 1;
+    LIST_INSERT_HEAD(&tprofile_all, fin, link);
+  }
+  pthread_mutex_unlock(&tprofile_mutex);
+  if (!fin) tprofile_destroy(tprof);
+}
+
+void tprofile_start1(tprofile_t *tprof, const char *id)
+{
+  pthread_mutex_lock(&tprofile_mutex);
+  assert(tprof->start == 0);
+  tprof->start = getfastmonoclock();
+  tprof->start_id = strdup(id);
+  pthread_mutex_unlock(&tprofile_mutex);
+}
+
+static void
+tprofile_time_replace(tprofile_time_t *tpt, const char *id, uint64_t t)
+{
+  free(tpt->id);
+  tpt->id = strdup(id);
+  tpt->t = t;
+}
+
+static void
+tprofile_avg_update(tprofile_avg_t *tpa, uint64_t val)
+{
+  tpa->avg = (tpa->avg * tpa->count + val) / (tpa->count + 1);
+  tpa->count++;
+}
+
+void tprofile_finish1(tprofile_t *tprof)
+{
+  if (tprof->start) {
+    uint64_t mono, diff;
+    pthread_mutex_lock(&tprofile_mutex);
+    mono = getfastmonoclock();
+    diff = mono - tprof->start;
+    if (diff > tprof->tmax.t)
+      tprofile_time_replace(&tprof->tmax, tprof->start_id, diff);
+    tprofile_avg_update(&tprof->tavg, diff);
+    free(tprof->start_id);
+    tprof->start_id = NULL;
+    tprof->start = 0;
+    tprof->changed = 1;
+    pthread_mutex_unlock(&tprofile_mutex);
+  }
+}
+
+void tprofile_queue_init1(qprofile_t *qprof, const char *name)
+{
+  memset(qprof, 0, sizeof(*qprof));
+  qprof->name = strdup(name);
+  pthread_mutex_lock(&qprofile_mutex);
+  LIST_INSERT_HEAD(&qprofile_all, qprof, link);
+  pthread_mutex_unlock(&qprofile_mutex);
+}
+
+static void qprofile_time_done(qprofile_time_t *qpt)
+{
+  free(qpt->id);
+}
+
+static void qprofile_avg_done(tprofile_avg_t *tpa)
+{
+}
+
+static void qprofile_destroy(qprofile_t *qprof)
+{
+  free(qprof->name);
+  qprofile_time_done(&qprof->qmax);
+  qprofile_avg_done(&qprof->qavg);
+}
+
+void tprofile_queue_done1(qprofile_t *qprof)
+{
+  qprofile_t *fin = malloc(sizeof(*fin));
+  pthread_mutex_lock(&qprofile_mutex);
+  LIST_REMOVE(qprof, link);
+  if (fin) {
+    *fin = *qprof;
+    fin->changed = fin->finish = 1;
+    LIST_INSERT_HEAD(&qprofile_all, fin, link);
+  }
+  pthread_mutex_unlock(&qprofile_mutex);
+  if (!fin) qprofile_destroy(qprof);
+}
+
+static void
+qprofile_time_replace(qprofile_time_t *qpt, const char *id, uint64_t t, uint64_t pos)
+{
+  free(qpt->id);
+  qpt->id = strdup(id);
+  qpt->t = t;
+  qpt->pos = pos;
+}
+
+static inline void
+qprofile_avg_update(qprofile_avg_t *tpa, uint64_t val)
+{
+  tprofile_avg_update((tprofile_avg_t *)tpa, val);
+}
+
+#include <stdio.h>
+
+void tprofile_queue_set1(qprofile_t *qprof, const char *id, uint64_t pos)
+{
+  uint64_t mono;
+  pthread_mutex_lock(&qprofile_mutex);
+  mono = getfastmonoclock();
+  if (pos > qprof->qmax.pos)
+    qprofile_time_replace(&qprof->qmax, id, mono, pos);
+  qprofile_avg_update(&qprof->qavg, pos);
+  qprof->changed = 1;
+  pthread_mutex_unlock(&qprofile_mutex);
+}
+
+void tprofile_queue_add1(qprofile_t *qprof, const char *id, uint64_t count)
+{
+  pthread_mutex_lock(&qprofile_mutex);
+  qprof->qsum += count;
+  pthread_mutex_unlock(&qprofile_mutex);
+}
+
+void tprofile_queue_drop1(qprofile_t *qprof, const char *id, uint64_t count)
+{
+  pthread_mutex_lock(&qprofile_mutex);
+  qprof->qdrop += count;
+  qprof->qdropcnt++;
+  pthread_mutex_unlock(&qprofile_mutex);
+}
+
+static void tprofile_log_tstats(void)
+{
+  tprofile_t *tprof, *tprof_next;
+
+  pthread_mutex_lock(&tprofile_mutex);
+  for (tprof = LIST_FIRST(&tprofile_all); tprof; tprof = tprof_next) {
+    tprof_next = LIST_NEXT(tprof, link);
+    if (tprof->changed == 0) continue;
+    tvhtrace(LS_TPROF, "%s: max/avg/cnt=%"PRIu64"ms/%"PRIu64"ms/%"PRIu64" (max=%s)%s",
+             tprof->name,
+             mono2ms(tprof->tmax.t),
+             mono2ms(tprof->tavg.avg), tprof->tavg.count,
+             tprof->tmax.id ?: "?",
+             tprof->finish ? " destroyed" : "");
+    if (tprof->finish) {
+      LIST_REMOVE(tprof, link);
+      tprofile_destroy(tprof);
+      free(tprof);
+      continue;
+    }
+    tprof->changed = 0;
+  }
+  pthread_mutex_unlock(&tprofile_mutex);
+}
+
+static void qprofile_log_qstats(void)
+{
+  qprofile_t *qprof, *qprof_next;
+  uint64_t mono, diff;
+
+  pthread_mutex_lock(&qprofile_mutex);
+  mono = getfastmonoclock();
+  for (qprof = LIST_FIRST(&qprofile_all); qprof; qprof = qprof_next) {
+    qprof_next = LIST_NEXT(qprof, link);
+    if (qprof->changed == 0) continue;
+    diff = qprof->tstamp ? mono - qprof->tstamp : 1;
+    tvhtrace(LS_QPROF, "%s: max/avg/cnt/drop/dropcnt=%"
+                       PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64
+                       " (max=%s -%"PRId64"sec) BW=%"PRId64"%s",
+             qprof->name,
+             qprof->qmax.pos,
+             qprof->qavg.avg, qprof->qavg.count,
+             qprof->qdrop, qprof->qdropcnt,
+             qprof->qmax.id, mono2sec(mono - qprof->qmax.t),
+             sec2mono(qprof->qsum) / diff,
+             qprof->finish ? " destroyed" : "");
+    if (qprof->finish) {
+      LIST_REMOVE(qprof, link);
+      qprofile_destroy(qprof);
+      free(qprof);
+      continue;
+    }
+    qprof->changed = 0;
+    qprof->qsum = 0;
+    qprof->tstamp = mono;
+  }
+  pthread_mutex_unlock(&qprofile_mutex);
+}
+
+void tprofile_log_stats1(void)
+{
+  tprofile_log_tstats();
+  qprofile_log_qstats();
+}
+
+char *tprofile_get_json_stats(void)
+{
+  return NULL;
+}
+
+void tprofile_module_init(int enable)
+{
+  tprofile_running = enable;
+  pthread_mutex_init(&tprofile_mutex, NULL);
+  pthread_mutex_init(&qprofile_mutex, NULL);
+}
+
+void tprofile_module_done(void)
+{
+  tprofile_log_stats1(); /* destroy all items in the finish state */
+  assert(LIST_FIRST(&tprofile_all) == NULL);
+  assert(LIST_FIRST(&qprofile_all) == NULL);
+}
diff --git a/src/tprofile.h b/src/tprofile.h
new file mode 100644 (file)
index 0000000..ddfba6e
--- /dev/null
@@ -0,0 +1,117 @@
+/*
+ *  tvheadend, Gather timing statistics - profiling
+ *  Copyright (C) 2018 Jaroslav Kysela
+ *
+ *  This program is free software: you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License as published by
+ *  the Free Software Foundation, either version 3 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU General Public License for more details.
+ *
+ *  You should have received a copy of the GNU General Public License
+ *  along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#ifndef __TVH_TPROFILE_H__
+#define __TVH_TPROFILE_H__
+
+#define STRINGIFY(s) # s
+#define SRCLINEID() SRCLINEID2(__FILE__, __LINE__)
+#define SRCLINEID2(f,l) f ":" STRINGIFY(l)
+
+typedef struct tprofile_avg tprofile_avg_t;
+typedef struct tprofile_time tprofile_time_t;
+typedef struct tprofile tprofile_t;
+typedef struct tprofile_avg qprofile_avg_t;
+typedef struct qprofile_time qprofile_time_t;
+typedef struct qprofile qprofile_t;
+
+struct tprofile_avg {
+  uint64_t count;
+  uint64_t avg;
+};
+
+struct tprofile_time {
+  uint64_t t;
+  char *id;
+};
+
+struct tprofile {
+  LIST_ENTRY(tprofile) link;
+  char *name;
+  tprofile_time_t tmax;
+  tprofile_avg_t tavg;
+  uint64_t start;
+  char *start_id;
+  uint8_t changed;
+  uint8_t finish;
+};
+
+struct qprofile_time {
+  uint64_t t;
+  uint64_t pos;
+  char *id;
+};
+
+struct qprofile {
+  LIST_ENTRY(qprofile) link;
+  char *name;
+  uint64_t qpos;
+  qprofile_time_t qmax;
+  tprofile_avg_t qavg;
+  uint64_t qsum;
+  uint64_t qdrop;
+  uint64_t qdropcnt;
+  uint64_t tstamp;
+  uint8_t changed;
+  uint8_t finish;
+};
+
+extern int tprofile_running;
+
+void tprofile_init1(tprofile_t *tprof, const char *name);
+void tprofile_done1(tprofile_t *tprof);
+void tprofile_start1(tprofile_t *tprof, const char *id);
+void tprofile_finish1(tprofile_t *tprof);
+
+static inline void tprofile_init(tprofile_t *tprof, const char *name)
+  { if (tprofile_running) tprofile_init1(tprof, name); }
+static inline void tprofile_done(tprofile_t *tprof)
+  { if (tprofile_running) tprofile_done1(tprof); }
+static inline void tprofile_start(tprofile_t *tprof, const char *id)
+  { if (tprofile_running) tprofile_start1(tprof, id); }
+static inline void tprofile_finish(tprofile_t *tprof)
+  { if (tprofile_running) tprofile_finish1(tprof); }
+
+void tprofile_queue_init1(qprofile_t *qprof, const char *name);
+void tprofile_queue_done1(qprofile_t *qprof);
+void tprofile_queue_set1(qprofile_t *qprof, const char *id, uint64_t pos);
+void tprofile_queue_add1(qprofile_t *qprof, const char *id, uint64_t pos);
+void tprofile_queue_drop1(qprofile_t *qprof, const char *id, uint64_t pos);
+
+static inline void tprofile_queue_init(qprofile_t *qprof, const char *name)
+  { if (tprofile_running) tprofile_queue_init1(qprof, name); }
+static inline void tprofile_queue_done(qprofile_t *qprof)
+  { if (tprofile_running) tprofile_queue_done1(qprof); }
+static inline void tprofile_queue_set(qprofile_t *qprof, const char *id, uint64_t pos)
+  { if (tprofile_running) tprofile_queue_set1(qprof, id, pos); }
+static inline void tprofile_queue_add(qprofile_t *qprof, const char *id, uint64_t pos)
+  { if (tprofile_running) tprofile_queue_add1(qprof, id, pos); }
+static inline void tprofile_queue_drop(qprofile_t *qprof, const char *id, uint64_t pos)
+  { if (tprofile_running) tprofile_queue_drop1(qprof, id, pos); }
+
+void tprofile_log_stats1(void);
+
+static inline void tprofile_log_stats(void)
+  { if (tprofile_running) tprofile_log_stats1(); }
+
+char *tprofile_get_json_stats(void);
+
+void tprofile_module_init(int enable);
+void tprofile_module_done(void);
+
+#endif /* __TVH_TPROFILE_H__ */
index 36e27574d6fc9c7e94c2b178a498a303a76d0c1d..4b09c77e23d624f7d49c626df42e034c1c436700 100644 (file)
 #include "queue.h"
 #include "hts_strtab.h"
 #include "htsmsg.h"
+#include "tprofile.h"
 #include "tvhlog.h"
 
 #include "redblack.h"
 
 #include "tvh_locale.h"
 
-#define STRINGIFY(s) # s
-#define SRCLINEID() SRCLINEID2(__FILE__, __LINE__)
-#define SRCLINEID2(f,l) f ":" STRINGIFY(l)
-
 #define ERRNO_AGAIN(e) ((e) == EAGAIN || (e) == EINTR || (e) == EWOULDBLOCK)
 
 #include "compat.h"
@@ -145,7 +142,7 @@ typedef struct {
  */
 
 #if ENABLE_GTIMER_CHECK
-#define GTIMER_TRACEID_ const char *id, const char *fcn,
+#define GTIMER_TRACEID_ const char *id,
 #define GTIMER_FCN(n) check_##n
 #else
 #define GTIMER_TRACEID_
@@ -165,7 +162,6 @@ typedef struct mtimer {
   int64_t mti_expire;
 #if ENABLE_GTIMER_CHECK
   const char *mti_id;
-  const char *mti_fcn;
 #endif
 } mtimer_t;
 
@@ -175,8 +171,8 @@ void GTIMER_FCN(mtimer_arm_abs)
   (GTIMER_TRACEID_ mtimer_t *mti, mti_callback_t *callback, void *opaque, int64_t when);
 
 #if ENABLE_GTIMER_CHECK
-#define mtimer_arm_rel(a, b, c, d) GTIMER_FCN(mtimer_arm_rel)(SRCLINEID(), __func__, a, b, c, d)
-#define mtimer_arm_abs(a, b, c, d) GTIMER_FCN(mtimer_arm_abs)(SRCLINEID(), __func__, a, b, c, d)
+#define mtimer_arm_rel(a, b, c, d) GTIMER_FCN(mtimer_arm_rel)(SRCLINEID(), a, b, c, d)
+#define mtimer_arm_abs(a, b, c, d) GTIMER_FCN(mtimer_arm_abs)(SRCLINEID(), a, b, c, d)
 #endif
 
 void mtimer_disarm(mtimer_t *mti);
@@ -196,7 +192,6 @@ typedef struct gtimer {
   time_t gti_expire;
 #if ENABLE_GTIMER_CHECK
   const char *gti_id;
-  const char *gti_fcn;
 #endif
 } gtimer_t;
 
@@ -206,8 +201,8 @@ void GTIMER_FCN(gtimer_arm_absn)
   (GTIMER_TRACEID_ gtimer_t *gti, gti_callback_t *callback, void *opaque, time_t when);
 
 #if ENABLE_GTIMER_CHECK
-#define gtimer_arm_rel(a, b, c, d) GTIMER_FCN(gtimer_arm_rel)(SRCLINEID(), __func__, a, b, c, d)
-#define gtimer_arm_absn(a, b, c, d) GTIMER_FCN(gtimer_arm_absn)(SRCLINEID(), __func__, a, b, c, d)
+#define gtimer_arm_rel(a, b, c, d) GTIMER_FCN(gtimer_arm_rel)(SRCLINEID(), a, b, c, d)
+#define gtimer_arm_absn(a, b, c, d) GTIMER_FCN(gtimer_arm_absn)(SRCLINEID(), a, b, c, d)
 #endif
 
 void gtimer_disarm(gtimer_t *gti);
index d2a84cce1e570307bb88af17da3a2f9245d058cd..ee5ed8f600562e2f64f8c061fd2a83f5c3e12eb1 100644 (file)
@@ -77,8 +77,8 @@ tvhlog_subsys_t tvhlog_subsystems[] = {
   [LS_CRASH]         = { "CRASH",         N_("CRASH") },
   [LS_CPU]           = { "CPU",           N_("CPU") },
   [LS_MAIN]          = { "main",          N_("Main") },
-  [LS_GTIMER]        = { "gtimer",        N_("Global timer") },
-  [LS_MTIMER]        = { "mtimer",        N_("Monitonic timer") },
+  [LS_TPROF]         = { "tprof",         N_("Time profiling") },
+  [LS_QPROF]         = { "qprof",         N_("Queue profiling") },
   [LS_THREAD]        = { "thread",        N_("Thread") },
   [LS_TVHPOLL]       = { "tvhpoll",       N_("Poll multiplexer") },
   [LS_TIME]          = { "time",          N_("Time") },
index 498cf3cd50cbb6f5ccb7c12cf806d745b5baff43..97a4310ade9a7647e8762bea6551a34be014e50a 100644 (file)
@@ -100,8 +100,8 @@ enum {
   LS_STOP,
   LS_CRASH,
   LS_MAIN,
-  LS_GTIMER,
-  LS_MTIMER,
+  LS_TPROF,
+  LS_QPROF,
   LS_CPU,
   LS_THREAD,
   LS_TVHPOLL,