From: Jaroslav Kysela Date: Sun, 8 Apr 2018 09:47:24 +0000 (+0200) Subject: added tprofile to gather code timings X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4fe0af0e8d9e47b1bbae5599bea09a772325a9f9;p=thirdparty%2Ftvheadend.git added tprofile to gather code timings --- diff --git a/Makefile b/Makefile index ac15d9423..c9667be17 100644 --- 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 \ diff --git a/src/input/mpegts.h b/src/input/mpegts.h index 777a9cfc9..6d88db94c 100644 --- a/src/input/mpegts.h +++ b/src/input/mpegts.h @@ -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 */ diff --git a/src/input/mpegts/mpegts_input.c b/src/input/mpegts/mpegts_input.c index 5464dcb43..b7bdf1d53 100644 --- a/src/input/mpegts/mpegts_input.c +++ b/src/input/mpegts/mpegts_input.c @@ -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); diff --git a/src/input/mpegts/mpegts_table.c b/src/input/mpegts/mpegts_table.c index 5f89450f3..df40748fb 100644 --- a/src/input/mpegts/mpegts_table.c +++ b/src/input/mpegts/mpegts_table.c @@ -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) { diff --git a/src/main.c b/src/main.c index 2cb16a190..47a00fa0d 100644 --- a/src/main.c +++ b/src/main.c @@ -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(>imers, 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(>imer_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(>imer_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(>imer_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(>imer_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 index 000000000..17568f257 --- /dev/null +++ b/src/tprofile.c @@ -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 . + */ + +#include +#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 + +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 index 000000000..ddfba6e9a --- /dev/null +++ b/src/tprofile.h @@ -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 . + */ + +#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__ */ diff --git a/src/tvheadend.h b/src/tvheadend.h index 36e27574d..4b09c77e2 100644 --- a/src/tvheadend.h +++ b/src/tvheadend.h @@ -38,16 +38,13 @@ #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); diff --git a/src/tvhlog.c b/src/tvhlog.c index d2a84cce1..ee5ed8f60 100644 --- a/src/tvhlog.c +++ b/src/tvhlog.c @@ -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") }, diff --git a/src/tvhlog.h b/src/tvhlog.h index 498cf3cd5..97a4310ad 100644 --- a/src/tvhlog.h +++ b/src/tvhlog.h @@ -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,