Commit ed72fea2 authored by Alessandro Rubini's avatar Alessandro Rubini Committed by Grzegorz Daniluk

latency: add syslog support (lost frames count is wrong)

If !CONFIG_SYSLOG, usual verbose output is printed to console.

If CONFIG_SYSLOG, you can send the latency error problems to syslog.
The node sends to syslog only the number of lost frames (FIX THIS)
and the latency if it's more than twice the current running average.
such an average is on 8 samples, so it moves quickly.
Signed-off-by: Alessandro Rubini's avatarAlessandro Rubini <rubini@gnudd.com>
parent fa7b151a
......@@ -110,6 +110,9 @@ config LATENCY_ETHTYPE
int
default 291
config LATENCY_SYSLOG
bool
# The other ones can be set by non-developers
config P2P
......@@ -495,6 +498,11 @@ config LATENCY_ETHTYPE
Ethertypes 0x0101-0x01ff are marked as "experimental", apparently.
So 0x0123 (291)is a good default, but please pick yours.
config LATENCY_SYSLOG
depends on LATENCY_PROBE && SYSLOG
bool "Report latency problems to syslog"
default y
# This is needed to size the pp_instance data strucuture. Instead of
# including the ppsi autoconf.h, with duplicate definitions, define it
# here, as we know what the value is
......
......@@ -65,5 +65,7 @@ int check_dest_ip(unsigned char *buf);
void syslog_init(void);
int syslog_poll(void);
void syslog_latency_report(int prio, struct wr_timestamp *lat, int lost[2]);
#endif
......@@ -12,6 +12,16 @@
#include <shell.h>
#include "ipv4.h"
#ifdef CONFIG_LATENCY_SYSLOG
#define HAS_SYSLOG 1
static int lat_verbose = 0;
#else
#define HAS_SYSLOG 0
static int lat_verbose = 1;
#endif
static unsigned long prios[] = {7, 6, 0}; /* the prio for the 3 frames */
/* latency probe: we need to enqueue 3 short frames: 64*3+overhead = 256 */
static uint8_t __latency_queue[256];
static struct wrpc_socket *latency_socket, __static_latency_socket = {
......@@ -35,7 +45,7 @@ static void latency_init(void)
static struct latency_frame {
uint32_t type; /* 1, 2, 3 */
uint32_t sequence;
struct wr_timestamp ts1, ts2;
struct wr_timestamp ts[2];
} frame;
static uint32_t prev_sequence, prev_type;
......@@ -57,6 +67,8 @@ static void ts_sub(struct wr_timestamp *t2, struct wr_timestamp *t1,
}
static void latency_warning(void) {
if (!lat_verbose)
return;
pp_printf("lat: unexpected %i.%i after %i.%i\n",
frame.sequence, frame.type, prev_sequence, prev_type);
}
......@@ -65,13 +77,14 @@ static int latency_poll_rx(void)
{
static struct wr_timestamp ts[2];
static int nframes;
static int lost[2];
struct wr_timestamp ts_tmp, lat[2];
struct wr_sockaddr addr;
int len;
int i, j;
len = ptpd_netif_recvfrom(latency_socket, &addr,
i = ptpd_netif_recvfrom(latency_socket, &addr,
&frame, sizeof(frame), &ts_tmp);
if (len < sizeof(frame))
if (i < sizeof(frame))
return 0;
/* check sequence and type is ok */
......@@ -102,6 +115,16 @@ static int latency_poll_rx(void)
}
break;
}
/* count lost frames */
i = prev_sequence * 3 + prev_type - 1; /* type: 1..3 -> 0..2 */
j = frame.sequence * 3 + frame.type - 2;
if (HAS_SYSLOG && j != i && j < i + 100) {
lost[1] = j;
lost[0] += j;
syslog_latency_report(-1, NULL, lost);
}
prev_sequence = frame.sequence;
prev_type = frame.type;
if (frame.type != 3 || nframes != 3)
......@@ -110,20 +133,38 @@ static int latency_poll_rx(void)
net_verbose("ts_rx 1: %9li.%09i.%03i\n", (long)ts[0].sec,
ts[0].nsec, ts[0].phase);
net_verbose("ts_tx 1: %9li.%09i.%03i\n", (long)frame.ts1.sec,
frame.ts1.nsec, frame.ts1.phase);
net_verbose("ts_tx 1: %9li.%09i.%03i\n", (long)frame.ts[0].sec,
frame.ts[0].nsec, frame.ts[0].phase);
net_verbose("ts_rx 2: %9li.%09i.%03i\n", (long)ts[1].sec,
ts[1].nsec, ts[1].phase);
net_verbose("ts_tx 2: %9li.%09i.%03i\n", (long)frame.ts2.sec,
frame.ts2.nsec, frame.ts2.phase);
ts_sub(ts + 0, &frame.ts1, lat + 0);
ts_sub(ts + 1, &frame.ts2, lat + 1);
pp_printf("lat: %9i %6i.%03i %6i.%03i\n",
frame.sequence,
lat[0].nsec, lat[0].phase,
lat[1].nsec, lat[1].phase);
net_verbose("ts_tx 2: %9li.%09i.%03i\n", (long)frame.ts[1].sec,
frame.ts[1].nsec, frame.ts[1].phase);
ts_sub(ts + 0, frame.ts + 0, lat + 0);
ts_sub(ts + 1, frame.ts + 1, lat + 1);
if (lat[0].sec || lat[1].sec)
return 1; /* not synchronized for sure */
if (lat_verbose) {
pp_printf("lat: %9i %6i.%03i %6i.%03i\n",
frame.sequence,
lat[0].nsec, lat[0].phase,
lat[1].nsec, lat[1].phase);
} else {
/* keep a running average of 8 samples */
static unsigned long avg_ns[2];
int i;
for (i = 0; i < 2; i++) {
if (!avg_ns[i])
avg_ns[i] = 2 * lat[i].nsec;
if (lat[i].nsec > avg_ns[i] * 2)
syslog_latency_report(prios[i], lat + i, lost);
avg_ns[i] = (7 * avg_ns[i] + lat[i].nsec) / 8;
}
}
return 1;
}
......@@ -137,25 +178,25 @@ static int latency_poll_tx(void)
frame.sequence = sequence++;
frame.type = 1;
latency_socket->prio = 7;
latency_socket->prio = prios[0];
ptpd_netif_sendto(latency_socket, &latency_addr, &frame, sizeof(frame),
&frame.ts1);
frame.ts + 0);
frame.type = 2;
latency_socket->prio = 6;
latency_socket->prio = prios[1];
ptpd_netif_sendto(latency_socket, &latency_addr, &frame, sizeof(frame),
&frame.ts2);
frame.ts + 1);
frame.type = 3;
latency_socket->prio = 0;
latency_socket->prio = prios[2];
ptpd_netif_sendto(latency_socket, &latency_addr, &frame, sizeof(frame),
NULL);
/* Every 10s remind we are sending ltest */
if (!lasts) {
lasts = frame.ts2.sec;
} else if (frame.ts2.sec - lasts >= 10) {
lasts = frame.ts2.sec;
lasts = frame.ts->sec;
} else if (frame.ts->sec - lasts >= 10) {
lasts = frame.ts->sec;
pp_printf("latency: seq %9i sent @ %9i\n",
sequence, lasts);
}
......@@ -192,12 +233,18 @@ static int cmd_ltest(const char *args[])
fromdec(args[1], &v1); /* ms */
}
if (args[0]) {
fromdec(args[0], &v);
latency_period_ms = v * 1000 + v1;
lastt = 0; /* reset, so it fires immediately */
if (HAS_SYSLOG && !strcmp(args[0], "verbose"))
lat_verbose = 1;
else if (HAS_SYSLOG && !strcmp(args[0], "quiet"))
lat_verbose = 0;
else {
fromdec(args[0], &v);
latency_period_ms = v * 1000 + v1;
lastt = 0; /* reset, so it fires immediately */
}
}
pp_printf("%i.%03i\n", latency_period_ms / 1000,
latency_period_ms % 1000);
pp_printf("%i.%03i (%s)\n", latency_period_ms / 1000,
latency_period_ms % 1000, lat_verbose ? "verbose" : "quiet");
return 0;
}
......
......@@ -70,9 +70,20 @@ static int syslog_header(char *buf, int level, unsigned char ip[4])
return len + UDP_END;
}
int syslog_poll(void)
static void syslog_send(void *buf, unsigned char *ip, int len)
{
struct wr_sockaddr addr;
memcpy(&syslog_addr.saddr, ip, 4);
fill_udp((void *)buf, len, &syslog_addr);
memcpy(&addr.mac, syslog_mac, 6);
ptpd_netif_sendto(syslog_socket, &addr, buf, len, 0);
return;
}
int syslog_poll(void)
{
char buf[256];
char b[32];
unsigned char mac[6];
......@@ -191,10 +202,32 @@ int syslog_poll(void)
return 0;
send:
memcpy(&syslog_addr.saddr, ip, 4);
fill_udp((void *)buf, len, &syslog_addr);
memcpy(&addr.mac, syslog_mac, 6);
ptpd_netif_sendto(syslog_socket, &addr, buf, len, 0);
return 1;
syslog_send(buf, ip, len);
}
#ifdef CONFIG_LATENCY_SYSLOG
void syslog_latency_report(int prio, struct wr_timestamp *ts, int lost[2])
{
char buf[256];
unsigned char ip[4];
int len;
if (ip_status == IP_TRAINING)
return;
if (!syslog_addr.daddr)
return;
len = syslog_header(buf, SYSLOG_DEFAULT_LEVEL, ip);
if (lost[1]) {
len += pp_sprintf(buf + len,
"ltest: lost %i frames (total %i)\n",
lost[1], lost[0]);
} else {
len += pp_sprintf(buf + len, "ltest: prio %i, %i ns\n",
prio, ts->nsec);
}
syslog_send(buf, ip, len);
}
#endif
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment