First try of implementation of measureing delay.

Will be squashed later.

daemon/Makefile

@@ -63,7 +63,7 @@ endif
 
 SRCS=		main.c kernel.c poller.c aux.c control_tcp.c streambuf.c call.c control_udp.c redis.c \
 		bencode.c cookie_cache.c udp_listener.c control_ng.c sdp.c str.c stun.c rtcp.c \
-		crypto.c rtp.c call_interfaces.c dtls.c log.c cli.c graphite.c
+		crypto.c rtp.c call_interfaces.c dtls.c log.c cli.c graphite.c measuredelay.c
 OBJS=		$(SRCS:.c=.o)
 
 

daemon/call.c

@@ -1344,6 +1344,12 @@ static void callmaster_timer(void *ptr) {
 		DS(bytes);
 		DS(errors);
 
+		mutex_lock(&m->statspslock);
+		ilog(LOG_INFO, "Start time:%llu\n", ke->stats.start.tv_nsec);
+		m->statsps.start = ke->stats.start;
+		m->statsps.end = ke->stats.end;
+		mutex_unlock(&m->statspslock);
+
 		mutex_lock(&ps->in_lock);
 
 		if (ke->stats.packets != ps->kernel_stats.packets)
@@ -1353,6 +1359,9 @@ static void callmaster_timer(void *ptr) {
 		ps->kernel_stats.bytes = ke->stats.bytes;
 		ps->kernel_stats.errors = ke->stats.errors;
 
+		ps->kernel_stats.start = ke->stats.start;
+		ps->kernel_stats.end = ke->stats.end;
+
 		update = 0;
 
 		sink = packet_stream_sink(ps);
@@ -2375,6 +2384,13 @@ static void unkernelize(struct packet_stream *p) {
 	PS_CLEAR(p, KERNELIZED);
 }
 
+void timespec_subtract (struct timespec *result, const struct timespec *a, const struct timespec *b) {
+	long long nanoseconds=0;
+	nanoseconds = ((long)a->tv_sec - (long long)b->tv_sec) * 1000000000 + ((long long)a->tv_nsec - (long long)b->tv_nsec);
+	result->tv_sec = nanoseconds/(long long)1000000000;
+	result->tv_nsec = nanoseconds%(long long)1000000000;
+}
+
 void timeval_subtract (struct timeval *result, const struct timeval *a, const struct timeval *b) {
 	long microseconds=0;
 	microseconds = ((long)a->tv_sec - (long)b->tv_sec) * 1000000 + ((long)a->tv_usec - (long)b->tv_usec);

daemon/call.h

@@ -190,6 +190,8 @@ struct stats {
 	u_int64_t			packets;
 	u_int64_t			bytes;
 	u_int64_t			errors;
+	struct timespec		start;
+	struct timespec		end;
 };
 
 struct totalstats {

daemon/cli.c

@@ -7,6 +7,8 @@
 #include <netinet/in.h>
 #include <errno.h>
 #include <glib.h>
+#include <time.h>
+#include <sys/time.h>
 
 #include "poller.h"
 #include "aux.h"
@@ -146,9 +148,10 @@ static void cli_incoming_list_callid(char* buffer, int len, struct callmaster* m
 
                if (PS_ISSET(ps, FALLBACK_RTCP))
                    continue;
-
+               struct timespec result;
+               timespec_subtract(&result,&(ps->stats.end),&(ps->stats.start));
                printlen = snprintf(replybuffer,(outbufend-replybuffer), "------ Media #%u, port %5u <> %15s:%-5hu%s, "
-                    "%llu p, %llu b, %llu e, %llu last_packet\n",
+                    "%llu p, %llu b, %llu e, %llu last_packet, %llu.%9llu delay\n",
                     md->index,
                     (unsigned int) (ps->sfd ? ps->sfd->fd.localport : 0),
                     smart_ntop_p_buf(&ps->endpoint.ip46), ps->endpoint.port,
@@ -156,7 +159,9 @@ static void cli_incoming_list_callid(char* buffer, int len, struct callmaster* m
                         (unsigned long long) ps->stats.packets,
                         (unsigned long long) ps->stats.bytes,
                         (unsigned long long) ps->stats.errors,
-                        (unsigned long long) ps->last_packet);
+                        (unsigned long long) ps->last_packet,
+						(unsigned long long) result.tv_sec,
+						(unsigned long long) result.tv_nsec);
                ADJUSTLEN(printlen,outbufend,replybuffer);
            }
        }

daemon/graphite.c

@@ -144,3 +144,4 @@ void graphite_loop_run(struct callmaster* callmaster, int seconds) {
 sleep:
 	usleep(100000);
 }
+

daemon/kernel.c

@@ -102,6 +102,20 @@ int kernel_del_stream(int fd, u_int16_t p) {
 	return -1;
 }
 
+int kernel_measure_delay(int fd) {
+	struct rtpengine_message msg;
+	int ret;
+
+	ZERO(msg);
+	msg.cmd = MMG_MEASUREDELAY;
+
+	ret = write(fd, &msg, sizeof(msg));
+	if (ret > 0)
+		return 0;
+
+	ilog(LOG_ERROR, "Failed to delete relay stream from kernel: %s", strerror(errno));
+	return -1;
+}
 
 GList *kernel_list(unsigned int id) {
 	char str[64];
@@ -119,6 +133,7 @@ GList *kernel_list(unsigned int id) {
 	for (;;) {
 		buf = g_slice_alloc(sizeof(*buf));
 		ret = read(fd, buf, sizeof(*buf));
+
 		if (ret != sizeof(*buf))
 			break;
 		li = g_list_prepend(li, buf);

daemon/main.c

@@ -27,6 +27,7 @@
 #include "call_interfaces.h"
 #include "cli.h"
 #include "graphite.h"
+#include "measuredelay.h"
 
 
 
@@ -629,6 +630,13 @@ static void timer_loop(void *d) {
 		poller_timers_wait_run(p, 100);
 }
 
+static void measuredelay_loop(void *d) {
+	struct callmaster *cm = d;
+
+	while (!global_shutdown)
+		measuredelay_loop_run(cm,1); // time in seconds
+}
+
 static void graphite_loop(void *d) {
 	struct callmaster *cm = d;
 
@@ -662,6 +670,7 @@ int main(int argc, char **argv) {
 
 	thread_create_detach(sighandler, NULL);
 	thread_create_detach(timer_loop, ctx.p);
+	thread_create_detach(measuredelay_loop, ctx.m);
 	if (graphite_ip)
 		thread_create_detach(graphite_loop, ctx.m);
 

daemon/measuredelay.c

@@ -0,0 +1,33 @@
+/*
+ * meauredelay.c
+ *
+ *  Created on: Feb 13, 2015
+ *      Author: fmetz
+ */
+
+#include "log.h"
+#include "call.h"
+#include "measuredelay.h"
+#include "kernel.h"
+
+static struct callmaster* cm=0;
+static time_t g_now, next_run;
+
+void measuredelay_loop_run(struct callmaster* callmaster, int seconds) {
+
+	int rc=0;
+
+	g_now = time(NULL);
+	if (g_now < next_run)
+		goto sleep;
+
+	next_run = g_now + seconds;
+
+	if (!cm)
+		cm = callmaster;
+
+	kernel_measure_delay(cm->conf.kernelfd);
+
+sleep:
+	usleep(100000);
+}

daemon/measuredelay.h

@@ -0,0 +1,14 @@
+/*
+ * measuredelay.h
+ *
+ *  Created on: Feb 13, 2015
+ *      Author: fmetz
+ */
+
+#ifndef MEASUREDELAY_H_
+#define MEASUREDELAY_H_
+
+void measuredelay_loop_run(struct callmaster* callmaster, int seconds);
+
+
+#endif /* MEASUREDELAY_H_ */

kernel-module/xt_RTPENGINE.c

@@ -1624,6 +1624,9 @@ static ssize_t proc_control_write(struct file *file, const char __user *buf, siz
 	struct rtpengine_table *t;
 	struct rtpengine_message msg;
 	int err;
+	int port;
+	struct rtpengine_target *g;
+	unsigned long flags;
 
 	if (buflen != sizeof(msg))
 		return -EIO;
@@ -1661,6 +1664,19 @@ static ssize_t proc_control_write(struct file *file, const char __user *buf, siz
 				goto err;
 			break;
 
+		case MMG_MEASUREDELAY:
+			port=0;
+			if (t==NULL)
+				break;
+			g = find_next_target(t, &port);
+			while (g != NULL) {
+				spin_lock_irqsave(&g->stats_lock, flags);
+				g->stats.measureactive=1;
+				spin_unlock_irqrestore(&g->stats_lock, flags);
+				g = find_next_target(t, &port);
+			}
+			break;
+
 		default:
 			printk(KERN_WARNING "xt_RTPENGINE unimplemented op %u\n", msg.cmd);
 			err = -EINVAL;
@@ -1792,6 +1808,8 @@ drop:
 
 
 static int send_proxy_packet(struct sk_buff *skb, struct re_address *src, struct re_address *dst, unsigned char tos) {
+	printk(KERN_WARNING "xt_RTPENGINE send_proxy_packet\n");
+
 	if (src->family != dst->family)
 		goto drop;
 
@@ -2105,7 +2123,7 @@ static inline int is_dtls(struct sk_buff *skb) {
 	return 1;
 }
 
-static unsigned int rtpengine46(struct sk_buff *skb, struct rtpengine_table *t, struct re_address *src) {
+static unsigned int rtpengine46(struct sk_buff *skb, struct rtpengine_table *t, struct re_address *src, struct timespec *starttime) {
 	struct udphdr *uh;
 	struct rtpengine_target *g;
 	struct sk_buff *skb2;
@@ -2212,8 +2230,15 @@ not_rtp:
 
 	err = send_proxy_packet(skb, &g->target.src_addr, &g->target.dst_addr, g->target.tos);
 
+
 out:
 	spin_lock_irqsave(&g->stats_lock, flags);
+	if (g->stats.measureactive==1) {
+		g->stats.start = *starttime;
+		getnstimeofday(&g->stats.end);
+		g->stats.measureactive=0;
+	}
+	printk(KERN_WARNING "xt_RTPENGINE failed to create /proc entry for ID %llu\n", g->stats.start.tv_nsec);
 	if (err)
 		g->stats.errors++;
 	else {
@@ -2254,6 +2279,8 @@ static unsigned int rtpengine4(struct sk_buff *oskb, const struct xt_action_para
 	struct iphdr *ih;
 	struct rtpengine_table *t;
 	struct re_address src;
+	struct timespec starttime;
+	getnstimeofday(&starttime);
 
 	t = get_table(pinfo->id);
 	if (!t)
@@ -2272,8 +2299,7 @@ static unsigned int rtpengine4(struct sk_buff *oskb, const struct xt_action_para
 	memset(&src, 0, sizeof(src));
 	src.family = AF_INET;
 	src.u.ipv4 = ih->saddr;
-
-	return rtpengine46(skb, t, &src);
+	return rtpengine46(skb, t, &src, &starttime);
 
 skip2:
 	kfree_skb(skb);
@@ -2296,6 +2322,8 @@ static unsigned int rtpengine6(struct sk_buff *oskb, const struct xt_action_para
 	struct ipv6hdr *ih;
 	struct rtpengine_table *t;
 	struct re_address src;
+	struct timespec starttime;
+	getnstimeofday(&starttime);
 
 	t = get_table(pinfo->id);
 	if (!t)
@@ -2314,8 +2342,7 @@ static unsigned int rtpengine6(struct sk_buff *oskb, const struct xt_action_para
 	memset(&src, 0, sizeof(src));
 	src.family = AF_INET6;
 	memcpy(&src.u.ipv6, &ih->saddr, sizeof(src.u.ipv6));
-
-	return rtpengine46(skb, t, &src);
+	return rtpengine46(skb, t, &src, &starttime);
 
 skip2:
 	kfree_skb(skb);

kernel-module/xt_RTPENGINE.h

@@ -9,6 +9,9 @@ struct rtpengine_stats {
 	u_int64_t			packets;
 	u_int64_t			bytes;
 	u_int64_t			errors;
+	struct timespec     start;
+	struct timespec     end;
+	u_int32_t			measureactive;
 };
 
 struct re_address {
@@ -86,6 +89,7 @@ struct rtpengine_message {
 		MMG_ADD,
 		MMG_DEL,
 		MMG_UPDATE,
+		MMG_MEASUREDELAY,
 	}				cmd;
 
 	struct rtpengine_target_info	target;