TT#12800 add MOS statistics to final log output

also converts call->created to a timeval

Change-Id: Idb71ada22a2d04637670b7515e54f2994f8d4c93

daemon/call.c

@@ -182,7 +182,7 @@ static void call_timer_iterator(void *key, void *val, void *ptr) {
 	rwlock_lock_r(&cm->conf.config_lock);
 
 	// final timeout applicable to all calls (own and foreign)
-	if (cm->conf.final_timeout && poller_now >= (c->created + cm->conf.final_timeout)) {
+	if (cm->conf.final_timeout && poller_now >= (c->created.tv_sec + cm->conf.final_timeout)) {
 		ilog(LOG_INFO, "Closing call due to final timeout");
 		tmp_t_reason = FINAL_TIMEOUT;
 		for (it = c->monologues.head; it; it = it->next) {
@@ -1845,66 +1845,91 @@ void call_destroy(struct call *c) {
 	rwlock_lock_w(&c->master_lock);
 	/* at this point, no more packet streams can be added */
 
-	if (IS_OWN_CALL(c)) {
-		ilog(LOG_INFO, "Final packet stats:");
+	if (!IS_OWN_CALL(c))
+		goto no_stats_output;
+
+	ilog(LOG_INFO, "Final packet stats:");
 
-		for (l = c->monologues.head; l; l = l->next) {
-			ml = l->data;
+	for (l = c->monologues.head; l; l = l->next) {
+		ml = l->data;
 
-			ilog(LOG_INFO, "--- Tag '"STR_FORMAT"', created "
-					"%u:%02u ago for branch '"STR_FORMAT"', in dialogue with '"STR_FORMAT"'",
-					STR_FMT(&ml->tag),
-					(unsigned int) (poller_now - ml->created) / 60,
-					(unsigned int) (poller_now - ml->created) % 60,
-					STR_FMT(&ml->viabranch),
-					ml->active_dialogue ? ml->active_dialogue->tag.len : 6,
-					ml->active_dialogue ? ml->active_dialogue->tag.s : "(none)");
+		ilog(LOG_INFO, "--- Tag '"STR_FORMAT"', created "
+				"%u:%02u ago for branch '"STR_FORMAT"', in dialogue with '"STR_FORMAT"'",
+				STR_FMT(&ml->tag),
+				(unsigned int) (poller_now - ml->created) / 60,
+				(unsigned int) (poller_now - ml->created) % 60,
+				STR_FMT(&ml->viabranch),
+				ml->active_dialogue ? ml->active_dialogue->tag.len : 6,
+				ml->active_dialogue ? ml->active_dialogue->tag.s : "(none)");
 
-			for (k = ml->medias.head; k; k = k->next) {
-				md = k->data;
+		for (k = ml->medias.head; k; k = k->next) {
+			md = k->data;
 
-				rtp_pt = __rtp_stats_codec(md);
+			rtp_pt = __rtp_stats_codec(md);
 #define MLL_PREFIX "------ Media #%u ("STR_FORMAT" over %s) using " /* media log line prefix */
 #define MLL_COMMON /* common args */						\
-					md->index,				\
-					STR_FMT(&md->type),			\
-					md->protocol ? md->protocol->name : "(unknown)"
-				if (!rtp_pt)
-					ilog(LOG_INFO, MLL_PREFIX "unknown codec", MLL_COMMON);
-				else
-					ilog(LOG_INFO, MLL_PREFIX STR_FORMAT, MLL_COMMON,
-							STR_FMT(&rtp_pt->encoding_with_params));
-
-				for (o = md->streams.head; o; o = o->next) {
-					ps = o->data;
-
-					if (PS_ISSET(ps, FALLBACK_RTCP))
-						continue;
-
-					char *addr = sockaddr_print_buf(&ps->endpoint.address);
-                                        char *local_addr = ps->selected_sfd ? sockaddr_print_buf(&ps->selected_sfd->socket.local.address) : "0.0.0.0";
-
-					ilog(LOG_INFO, "--------- Port %15s:%-5u <> %15s:%-5u%s, SSRC %" PRIu32 ", "
-							""UINT64F" p, "UINT64F" b, "UINT64F" e, "UINT64F" last_packet",
-							local_addr,
-							(unsigned int) (ps->selected_sfd ? ps->selected_sfd->socket.local.port : 0),
-							addr, ps->endpoint.port,
-							(!PS_ISSET(ps, RTP) && PS_ISSET(ps, RTCP)) ? " (RTCP)" : "",
-							ps->ssrc_in ? ps->ssrc_in->parent->ssrc : 0,
-							atomic64_get(&ps->stats.packets),
-							atomic64_get(&ps->stats.bytes),
-							atomic64_get(&ps->stats.errors),
-							atomic64_get(&ps->last_packet));
-
-					statistics_update_totals(m,ps);
+				md->index,				\
+				STR_FMT(&md->type),			\
+				md->protocol ? md->protocol->name : "(unknown)"
+			if (!rtp_pt)
+				ilog(LOG_INFO, MLL_PREFIX "unknown codec", MLL_COMMON);
+			else
+				ilog(LOG_INFO, MLL_PREFIX STR_FORMAT, MLL_COMMON,
+						STR_FMT(&rtp_pt->encoding_with_params));
 
-				}
+			for (o = md->streams.head; o; o = o->next) {
+				ps = o->data;
+
+				if (PS_ISSET(ps, FALLBACK_RTCP))
+					continue;
+
+				char *addr = sockaddr_print_buf(&ps->endpoint.address);
+				char *local_addr = ps->selected_sfd ? sockaddr_print_buf(&ps->selected_sfd->socket.local.address) : "0.0.0.0";
+
+				ilog(LOG_INFO, "--------- Port %15s:%-5u <> %15s:%-5u%s, SSRC %" PRIu32 ", "
+						""UINT64F" p, "UINT64F" b, "UINT64F" e, "UINT64F" ts",
+						local_addr,
+						(unsigned int) (ps->selected_sfd ? ps->selected_sfd->socket.local.port : 0),
+						addr, ps->endpoint.port,
+						(!PS_ISSET(ps, RTP) && PS_ISSET(ps, RTCP)) ? " (RTCP)" : "",
+						ps->ssrc_in ? ps->ssrc_in->parent->ssrc : 0,
+						atomic64_get(&ps->stats.packets),
+						atomic64_get(&ps->stats.bytes),
+						atomic64_get(&ps->stats.errors),
+						g_now.tv_sec - atomic64_get(&ps->last_packet));
+
+				statistics_update_totals(m,ps);
 
-				ice_shutdown(&md->ice_agent);
 			}
+
+			ice_shutdown(&md->ice_agent);
 		}
 	}
 
+	k = g_hash_table_get_values(c->ssrc_hash->ht);
+	for (l = k; l; l = l->next) {
+		struct ssrc_entry *se = l->data;
+
+		if (!se->stats_blocks.length || !se->lowest_mos || !se->highest_mos)
+			continue;
+
+		ilog(LOG_INFO, "--- SSRC %" PRIu32 "", se->ssrc);
+		ilog(LOG_INFO, "------ Average MOS %i.%i, lowest MOS %i.%i (at %u:%02u), "
+				"highest MOS %i.%i (at %u:%02u)",
+			(int) (se->mos_sum / se->stats_blocks.length / 10),
+			abs(se->mos_sum / se->stats_blocks.length % 10),
+			se->lowest_mos->mos / 10,
+			abs(se->lowest_mos->mos % 10),
+			(unsigned int) (timeval_diff(&se->lowest_mos->reported, &c->created) / 1000000) / 60,
+			(unsigned int) (timeval_diff(&se->lowest_mos->reported, &c->created) / 1000000) % 60,
+			se->highest_mos->mos / 10,
+			abs(se->highest_mos->mos % 10),
+			(unsigned int) (timeval_diff(&se->highest_mos->reported, &c->created) / 1000000) / 60,
+			(unsigned int) (timeval_diff(&se->highest_mos->reported, &c->created) / 1000000) % 60);
+	}
+	g_list_free(k);
+
+no_stats_output:
 	statistics_update_oneway(c);
 
 	cdr_update_entry(c);
@@ -2033,7 +2058,7 @@ static struct call *call_create(const str *callid, struct callmaster *m) {
 	c->tags = g_hash_table_new(str_hash, str_equal);
 	c->viabranches = g_hash_table_new(str_hash, str_equal);
 	call_str_cpy(c, &c->callid, callid);
-	c->created = poller_now;
+	c->created = g_now;
 	c->dtls_cert = dtls_cert();
 	c->tos = m->conf.default_tos;
 	c->ssrc_hash = create_ssrc_hash();

daemon/call.h

@@ -372,7 +372,7 @@ struct call {
 	struct ssrc_hash	*ssrc_hash;
 
 	str			callid;
-	time_t			created;
+	struct timeval		created;
 	time_t			last_signal;
 	time_t			deleted;
 	time_t			ml_deleted;

daemon/call_interfaces.c

@@ -427,9 +427,9 @@ static void call_status_iterator(struct call *c, struct control_stream *s) {
 //	m = c->callmaster;
 //	mutex_lock(&c->master_lock);
 
-	control_stream_printf(s, "session "STR_FORMAT" - - - - %i\n",
+	control_stream_printf(s, "session "STR_FORMAT" - - - - %lli\n",
 		STR_FMT(&c->callid),
-		(int) (poller_now - c->created));
+		timeval_diff(&g_now, &c->created) / 1000000);
 
 	/* XXX restore function */
 
@@ -1021,7 +1021,8 @@ void ng_call_stats(struct call *call, const str *fromtag, const str *totag, benc
 
 	call_bencode_hold_ref(call, output);
 
-	bencode_dictionary_add_integer(output, "created", call->created);
+	bencode_dictionary_add_integer(output, "created", call->created.tv_sec);
+	bencode_dictionary_add_integer(output, "created_us", call->created.tv_usec);
 	bencode_dictionary_add_integer(output, "last signal", call->last_signal);
 
 	tags = bencode_dictionary_add_dictionary(output, "tags");

daemon/cli.c

@@ -283,7 +283,7 @@ static void cli_incoming_list_callid(char* buffer, int len, struct callmaster* m
    }
 
    printlen = snprintf (replybuffer,(outbufend-replybuffer), "\ncallid: %60s | deletionmark:%4s | created:%12i  | proxy:%s | tos:%u | last_signal:%llu | redis_keyspace:%i | foreign:%s\n\n",
-		   c->callid.s , c->ml_deleted?"yes":"no", (int)c->created, c->created_from, (unsigned int)c->tos, (unsigned long long)c->last_signal, c->redis_hosted_db, IS_FOREIGN_CALL(c)?"yes":"no");
+		   c->callid.s , c->ml_deleted?"yes":"no", (int)c->created.tv_sec, c->created_from, (unsigned int)c->tos, (unsigned long long)c->last_signal, c->redis_hosted_db, IS_FOREIGN_CALL(c)?"yes":"no");
    ADJUSTLEN(printlen,outbufend,replybuffer);
 
    for (l = c->monologues.head; l; l = l->next) {
@@ -417,7 +417,7 @@ static void cli_incoming_list_sessions(char* buffer, int len, struct callmaster*
 			break;
 		}
 
-		printlen = snprintf(replybuffer, outbufend-replybuffer, "callid: %60s | deletionmark:%4s | created:%12i | proxy:%s | redis_keyspace:%i | foreign:%s\n", ptrkey->s, call->ml_deleted?"yes":"no", (int)call->created, call->created_from, call->redis_hosted_db, IS_FOREIGN_CALL(call)?"yes":"no");
+		printlen = snprintf(replybuffer, outbufend-replybuffer, "callid: %60s | deletionmark:%4s | created:%12i | proxy:%s | redis_keyspace:%i | foreign:%s\n", ptrkey->s, call->ml_deleted?"yes":"no", (int)call->created.tv_sec, call->created_from, call->redis_hosted_db, IS_FOREIGN_CALL(call)?"yes":"no");
 		ADJUSTLEN(printlen,outbufend,replybuffer);
 	}
 	rwlock_unlock_r(&m->hashlock);

daemon/recording.c

@@ -369,7 +369,7 @@ static int pcap_meta_finish_file(struct call *call) {
 
 	// Print start timestamp and end timestamp
 	// YYYY-MM-DDThh:mm:ss
-	time_t start = call->created;
+	time_t start = call->created.tv_sec;
 	time_t end = g_now.tv_sec;
 	char timebuffer[20];
 	struct tm *timeinfo;

daemon/redis.c

@@ -797,8 +797,15 @@ static atomic64 strtoa64(const char *c, char **endp, int base) {
 	atomic64_set_na(&ret, u);
 	return ret;
 }
+static struct timeval strtotimeval(const char *c, char **endp, int base) {
+	long long ll = strtoll(c, endp, base);
+	struct timeval ret;
+	timeval_from_us(&ret, ll);
+	return ret;
+}
 
 define_get_int_type(time_t, time_t, strtoull);
+define_get_int_type(timeval, struct timeval, strtotimeval);
 define_get_int_type(int, int, strtol);
 define_get_int_type(unsigned, unsigned int, strtol);
 //define_get_int_type(u16, u_int16_t, strtol);
@@ -1427,7 +1434,7 @@ static void json_restore_call(struct redis *r, struct callmaster *m, const str *
 		goto err7;
 
 	err = "missing 'created' timestamp";
-	if (redis_hash_get_time_t(&c->created, &call, "created"))
+	if (redis_hash_get_timeval(&c->created, &call, "created"))
 		goto err8;
 	err = "missing 'last signal' timestamp";
 	if (redis_hash_get_time_t(&c->last_signal, &call, "last_signal"))
@@ -1697,7 +1704,7 @@ char* redis_encode_json(struct call *c) {
 		json_builder_begin_object (builder);
 
 		{
-			JSON_SET_SIMPLE("created","%ld",(long int) c->created);
+			JSON_SET_SIMPLE("created","%lli", timeval_us(&c->created));
 			JSON_SET_SIMPLE("last_signal","%ld",(long int) c->last_signal);
 			JSON_SET_SIMPLE("tos","%u",(int) c->tos);
 			JSON_SET_SIMPLE("deleted","%ld",(long int) c->deleted);

daemon/ssrc.c

@@ -41,7 +41,7 @@ static void free_ssrc_entry(void *p) {
 static void mos_calc(struct ssrc_stats_block *ssb) {
 	// as per https://www.pingman.com/kb/article/how-is-mos-calculated-in-pingplotter-pro-50.html
 	int eff_rtt = ssb->rtt / 1000 + ssb->jitter * 2 + 10;
-	double r;
+	double r; // XXX can this be done with int math?
 	if (eff_rtt < 160)
 		r = 93.2 - eff_rtt / 40.0;
 	else
@@ -211,8 +211,26 @@ found:
 
 	// got a new stats block, add it to reporting ssrc
 	e = get_ssrc(rr->from, c->ssrc_hash);
+
 	mutex_lock(&e->lock);
+
+	// discard stats block if last has been received less than a second ago
+	if (G_LIKELY(e->stats_blocks.length > 0)) {
+		struct ssrc_stats_block *last_ssb = g_queue_peek_tail(&e->stats_blocks);
+		if (G_UNLIKELY(timeval_diff(tv, &last_ssb->reported) < 1000000)) {
+			free_stats_block(ssb);
+			goto out;
+		}
+	}
+
 	g_queue_push_tail(&e->stats_blocks, ssb);
+
+	if (G_UNLIKELY(!e->lowest_mos) || ssb->mos < e->lowest_mos->mos)
+		e->lowest_mos = ssb;
+	if (G_UNLIKELY(!e->highest_mos) || ssb->mos > e->highest_mos->mos)
+		e->highest_mos = ssb;
+	e->mos_sum += ssb->mos;
+
 	goto out;
 
 out:

daemon/ssrc.h

@@ -37,6 +37,9 @@ struct ssrc_entry {
 			output_ctx;
 	GQueue sender_reports; // as received via RTCP
 	GQueue stats_blocks; // calculated
+	struct ssrc_stats_block *lowest_mos,
+				*highest_mos;
+	u_int64_t mos_sum;
 	int payload_type; // to determine the clock rate for jitter calculations
 	unsigned int last_rtt; // last calculated raw rtt without rtt from opposide side
 };