Skip to content

Commit 317d551

Browse files
jukkarjukkar
committed
net: Add statistics about time spent in TX and RX path
This is not very scientific but can give some hint how much we are spending in TX and RX paths. Signed-off-by: Jukka Rissanen <[email protected]>
1 parent 3bbf067 commit 317d551

File tree

10 files changed

+233
-11
lines changed

10 files changed

+233
-11
lines changed

‎drivers/ethernet/eth_mcux.c‎

Lines changed: 18 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -652,12 +652,20 @@ static void eth_rx(struct device *iface)
652652
&ptpTimeData) &&
653653
(ENET_GetRxFrameTime(&context->enet_handle,
654654
&ptpTimeData) == kStatus_Success)) {
655-
pkt->timestamp.nanosecond = ptpTimeData.timeStamp.nanosecond;
656-
pkt->timestamp.second = ptpTimeData.timeStamp.second;
655+
struct net_ptp_time timestamp = {
656+
.second = ptpTimeData.timeStamp.second,
657+
.nanosecond = ptpTimeData.timeStamp.nanosecond,
658+
};
659+
660+
net_pkt_set_timestamp(pkt, &timestamp);
657661
} else {
658662
/* Invalid value. */
659-
pkt->timestamp.nanosecond = UINT32_MAX;
660-
pkt->timestamp.second = UINT64_MAX;
663+
struct net_ptp_time timestamp = {
664+
.second = UINT64_MAX,
665+
.nanosecond = UINT32_MAX,
666+
};
667+
668+
net_pkt_set_timestamp(pkt, &timestamp);
661669
}
662670
#endif /* CONFIG_NET_PKT_TIMESTAMP */
663671

@@ -682,10 +690,12 @@ static inline void ts_register_tx_event(struct eth_context *context)
682690
status = ENET_GetTxFrameTime(&context->enet_handle,
683691
&timeData);
684692
if (status == kStatus_Success) {
685-
pkt->timestamp.nanosecond =
686-
timeData.timeStamp.nanosecond;
687-
pkt->timestamp.second =
688-
timeData.timeStamp.second;
693+
struct net_ptp_time timestamp = {
694+
.second = timeData.timeStamp.second,
695+
.nanosecond = timeData.timeStamp.nanosecond,
696+
};
697+
698+
net_pkt_set_timestamp(pkt, &timestamp);
689699

690700
net_if_add_tx_timestamp(pkt);
691701
}

‎include/net/net_if.h‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1631,6 +1631,25 @@ void net_if_call_timestamp_cb(struct net_pkt *pkt);
16311631
* @param pkt Timestamped buffer
16321632
*/
16331633
void net_if_add_tx_timestamp(struct net_pkt *pkt);
1634+
1635+
#if defined(CONFIG_NET_STATISTICS)
1636+
/*
1637+
* @brief Update Rx packet handling statistics
1638+
*
1639+
* @param pkt Received network packet
1640+
*/
1641+
void net_if_update_rx_timestamp_stats(struct net_pkt *pkt);
1642+
1643+
/*
1644+
* @brief Update Tx packet handling statistics
1645+
*
1646+
* @param pkt Sent network packet
1647+
*/
1648+
void net_if_update_tx_timestamp_stats(struct net_pkt *pkt);
1649+
#else
1650+
#define net_if_update_rx_timestamp_stats(pkt)
1651+
#define net_if_update_tx_timestamp_stats(pkt)
1652+
#endif /* CONFIG_NET_STATISTICS */
16341653
#endif /* CONFIG_NET_PKT_TIMESTAMP */
16351654

16361655
struct net_if_api {

‎include/net/net_pkt.h‎

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -78,6 +78,14 @@ struct net_pkt {
7878
#if defined(CONFIG_NET_PKT_TIMESTAMP)
7979
/** Timestamp if available. */
8080
struct net_ptp_time timestamp;
81+
#if defined(CONFIG_NET_STATISTICS)
82+
/** This is used for collecting statistics. This is updated by
83+
* the driver so it is not fully accurate. This is done using hw cycles
84+
* as we do not have an API that would return time in nanoseconds.
85+
*/
86+
u32_t cycles_create;
87+
u32_t cycles_update;
88+
#endif
8189
#endif
8290

8391
u8_t *appdata; /* application data starts here */
@@ -155,6 +163,9 @@ struct net_pkt {
155163
* is not prioritised.
156164
*/
157165
u8_t priority;
166+
167+
/** Traffic class value. */
168+
u8_t traffic_class;
158169
#endif
159170

160171
#if defined(CONFIG_NET_VLAN)
@@ -425,11 +436,33 @@ static inline void net_pkt_set_priority(struct net_pkt *pkt,
425436
{
426437
pkt->priority = priority;
427438
}
439+
440+
static inline u8_t net_pkt_traffic_class(struct net_pkt *pkt)
441+
{
442+
return pkt->traffic_class;
443+
}
444+
445+
static inline void net_pkt_set_traffic_class(struct net_pkt *pkt, u8_t tc)
446+
{
447+
pkt->traffic_class = tc;
448+
}
428449
#else
429450
static inline u8_t net_pkt_priority(struct net_pkt *pkt)
430451
{
431452
return 0;
432453
}
454+
455+
static inline u8_t net_pkt_traffic_class(struct net_pkt *pkt)
456+
{
457+
ARG_UNUSED(pkt);
458+
return 0;
459+
}
460+
461+
static inline void net_pkt_set_traffic_class(struct net_pkt *pkt, u8_t tc)
462+
{
463+
ARG_UNUSED(pkt);
464+
ARG_UNUSED(tc);
465+
}
433466
#endif
434467

435468
#if defined(CONFIG_NET_VLAN)
@@ -525,6 +558,10 @@ static inline void net_pkt_set_timestamp(struct net_pkt *pkt,
525558
{
526559
pkt->timestamp.second = timestamp->second;
527560
pkt->timestamp.nanosecond = timestamp->nanosecond;
561+
562+
#if defined(CONFIG_NET_STATISTICS)
563+
pkt->cycles_update = k_cycle_get_32();
564+
#endif
528565
}
529566
#else
530567
static inline struct net_ptp_time *net_pkt_timestamp(struct net_pkt *pkt)

‎include/net/net_stats.h‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -250,6 +250,27 @@ struct net_stats_tc {
250250
} recv[NET_TC_RX_COUNT];
251251
};
252252

253+
struct net_stats_ts_data {
254+
/** Processing time in nanoseconds */
255+
u32_t low;
256+
u32_t average;
257+
u32_t high;
258+
};
259+
260+
struct net_stats_ts {
261+
/** Network packet timestamping statistics. This tells how many
262+
* nanoseconds it took for packet to transmit or receive. This
263+
* is only calculated for those packets that have TX time-stamping
264+
* enabled.
265+
*/
266+
struct {
267+
struct net_stats_ts_data time;
268+
} tx[NET_TC_TX_COUNT];
269+
270+
struct {
271+
struct net_stats_ts_data time;
272+
} rx[NET_TC_RX_COUNT];
273+
};
253274

254275
struct net_stats {
255276
net_stats_t processing_error;
@@ -297,6 +318,10 @@ struct net_stats {
297318
#if NET_TC_COUNT > 1
298319
struct net_stats_tc tc;
299320
#endif
321+
322+
#if defined(CONFIG_NET_PKT_TIMESTAMP)
323+
struct net_stats_ts ts;
324+
#endif
300325
};
301326

302327
struct net_stats_eth_errors {

‎subsys/net/ip/l2/gptp/gptp.c‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -146,6 +146,8 @@ static void gptp_handle_msg(struct net_pkt *pkt)
146146
pdelay_req_state = &GPTP_PORT_STATE(port)->pdelay_req;
147147
sync_rcv_state = &GPTP_PORT_STATE(port)->sync_rcv;
148148

149+
net_if_update_rx_timestamp_stats(pkt);
150+
149151
switch (hdr->message_type) {
150152
case GPTP_SYNC_MESSAGE:
151153
if (GPTP_CHECK_LEN(pkt, GPTP_SYNC_LEN)) {

‎subsys/net/ip/net_core.c‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -335,6 +335,8 @@ static void net_queue_rx(struct net_if *iface, struct net_pkt *pkt)
335335
NET_DBG("TC %d with prio %d pkt %p", tc, prio, pkt);
336336
#endif
337337

338+
net_pkt_set_traffic_class(pkt, tc);
339+
338340
net_tc_submit_to_rx_queue(tc, pkt);
339341
}
340342

‎subsys/net/ip/net_if.c‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
#include <kernel.h>
1414
#include <linker/sections.h>
1515
#include <string.h>
16+
#include <stdlib.h>
1617
#include <net/net_core.h>
1718
#include <net/net_pkt.h>
1819
#include <net/net_if.h>
@@ -219,6 +220,8 @@ void net_if_queue_tx(struct net_if *iface, struct net_pkt *pkt)
219220
NET_DBG("TC %d with prio %d pkt %p", tc, prio, pkt);
220221
#endif
221222

223+
net_pkt_set_traffic_class(pkt, tc);
224+
222225
net_tc_submit_to_tx_queue(tc, pkt);
223226
}
224227

@@ -2173,6 +2176,29 @@ int net_if_down(struct net_if *iface)
21732176
}
21742177

21752178
#if defined(CONFIG_NET_PKT_TIMESTAMP)
2179+
#if defined(CONFIG_NET_STATISTICS)
2180+
void net_if_update_rx_timestamp_stats(struct net_pkt *pkt)
2181+
{
2182+
u32_t now = k_cycle_get_32();
2183+
s32_t diff = (s32_t)(now - pkt->cycles_update);
2184+
2185+
diff = abs(diff);
2186+
2187+
net_stats_update_pkt_rx_timestamp(net_pkt_traffic_class(pkt),
2188+
SYS_CLOCK_HW_CYCLES_TO_NS64(diff));
2189+
}
2190+
2191+
void net_if_update_tx_timestamp_stats(struct net_pkt *pkt)
2192+
{
2193+
s32_t diff = (s32_t)(pkt->cycles_update - pkt->cycles_create);
2194+
2195+
diff = abs(diff);
2196+
2197+
net_stats_update_pkt_tx_timestamp(net_pkt_traffic_class(pkt),
2198+
SYS_CLOCK_HW_CYCLES_TO_NS64(diff));
2199+
}
2200+
#endif /* CONFIG_NET_STATISTICS */
2201+
21762202
static void net_tx_ts_thread(void)
21772203
{
21782204
struct net_pkt *pkt;
@@ -2182,6 +2208,8 @@ static void net_tx_ts_thread(void)
21822208
while (1) {
21832209
pkt = k_fifo_get(&tx_ts_queue, K_FOREVER);
21842210
if (pkt) {
2211+
net_if_update_tx_timestamp_stats(pkt);
2212+
21852213
net_if_call_timestamp_cb(pkt);
21862214
}
21872215

‎subsys/net/ip/net_pkt.c‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -324,6 +324,10 @@ struct net_pkt *net_pkt_get_reserve(struct k_mem_slab *slab,
324324

325325
net_pkt_set_vlan_tag(pkt, NET_VLAN_TAG_UNSPEC);
326326

327+
#if defined(CONFIG_NET_PKT_TIMESTAMP) && defined(CONFIG_NET_STATISTICS)
328+
pkt->cycles_create = k_cycle_get_32();
329+
#endif
330+
327331
#if defined(CONFIG_NET_DEBUG_NET_PKT)
328332
net_pkt_alloc_add(pkt, true, caller, line);
329333

‎subsys/net/ip/net_shell.c‎

Lines changed: 47 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -644,7 +644,7 @@ static void net_shell_print_statistics(struct net_if *iface, void *user_data)
644644

645645
#if NET_TC_TX_COUNT > 1
646646
printk("TX traffic class statistics:\n");
647-
printk("TC Priority\tSent pkts\tbytes\n");
647+
printk("TC Priority\tSent pkts\tbytes\n");
648648

649649
for (i = 0; i < NET_TC_TX_COUNT; i++) {
650650
printk("[%d] %s (%d)\t%d\t\t%d\n", i,
@@ -658,7 +658,7 @@ static void net_shell_print_statistics(struct net_if *iface, void *user_data)
658658

659659
#if NET_TC_RX_COUNT > 1
660660
printk("RX traffic class statistics:\n");
661-
printk("TC Priority\tRecv pkts\tbytes\n");
661+
printk("TC Priority\tRecv pkts\tbytes\n");
662662

663663
for (i = 0; i < NET_TC_RX_COUNT; i++) {
664664
printk("[%d] %s (%d)\t%d\t\t%d\n", i,
@@ -668,9 +668,53 @@ static void net_shell_print_statistics(struct net_if *iface, void *user_data)
668668
GET_STAT(iface, tc.recv[i].pkts),
669669
GET_STAT(iface, tc.recv[i].bytes));
670670
}
671-
}
672671
#endif
672+
}
673673
#endif /* NET_TC_COUNT > 1 */
674+
675+
#if (NET_TC_COUNT > 1) && defined(CONFIG_NET_PKT_TIMESTAMP)
676+
{
677+
int i;
678+
679+
#if NET_TC_TX_COUNT > 1
680+
printk("TX timestamp statistics:\n");
681+
printk("TC Low\tAvg\tHigh (in nanoseconds)\n");
682+
683+
for (i = 0; i < NET_TC_TX_COUNT; i++) {
684+
if (GET_STAT(ts.tx[i].time.low) == 0 &&
685+
GET_STAT(ts.tx[i].time.average) == 0 &&
686+
GET_STAT(ts.tx[i].time.high) == 0) {
687+
continue;
688+
}
689+
690+
printk("[%d] %s %u\t%u\t%u\n", i,
691+
priority2str(GET_STAT(tc.sent[i].priority)),
692+
GET_STAT(ts.tx[i].time.low),
693+
GET_STAT(ts.tx[i].time.average),
694+
GET_STAT(ts.tx[i].time.high));
695+
}
696+
#endif
697+
698+
#if NET_TC_RX_COUNT > 1
699+
printk("RX timestamp statistics:\n");
700+
printk("TC Low\tAvg\tHigh (in nanoseconds)\n");
701+
702+
for (i = 0; i < NET_TC_RX_COUNT; i++) {
703+
if (GET_STAT(ts.rx[i].time.low) == 0 &&
704+
GET_STAT(ts.rx[i].time.average) == 0 &&
705+
GET_STAT(ts.rx[i].time.high) == 0) {
706+
continue;
707+
}
708+
709+
printk("[%d] %s %u\t%u\t%u\n", i,
710+
priority2str(GET_STAT(tc.recv[i].priority)),
711+
GET_STAT(ts.rx[i].time.low),
712+
GET_STAT(ts.rx[i].time.average),
713+
GET_STAT(ts.rx[i].time.high));
714+
}
715+
#endif
716+
}
717+
#endif /* (NET_TC_COUNT > 1) && CONFIG_NET_PKT_TIMESTAMP */
674718
}
675719
#endif /* CONFIG_NET_STATISTICS */
676720

‎subsys/net/ip/net_stats.h‎

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -506,6 +506,57 @@ static inline void net_stats_update_tc_recv_priority(struct net_if *iface,
506506
#define net_stats_update_tc_recv_priority(iface, tc, priority)
507507
#endif /* NET_TC_COUNT > 1 */
508508

509+
#if defined(CONFIG_NET_PKT_TIMESTAMP) && defined(CONFIG_NET_STATISTICS)
510+
#define _NET_STATS_AVG_SAMPLES 100
511+
512+
static inline
513+
void _net_stats_update_pkt_timestamp(struct net_stats_ts_data *data,
514+
u32_t ts)
515+
{
516+
if (ts == UINT32_MAX || ts == 0) {
517+
return;
518+
}
519+
520+
/* Do not calculate highest or lowest number into rolling average */
521+
522+
if (ts < data->low || data->low == 0) {
523+
data->low = ts;
524+
return;
525+
}
526+
527+
if (ts > data->high) {
528+
data->high = ts;
529+
return;
530+
}
531+
532+
if (data->average) {
533+
if (ts > (10 * data->average)) {
534+
/* If the time is too large, just skip it */
535+
return;
536+
}
537+
538+
data->average = (data->average *
539+
(_NET_STATS_AVG_SAMPLES - 1) + ts) /
540+
_NET_STATS_AVG_SAMPLES;
541+
} else {
542+
data->average = ts;
543+
}
544+
}
545+
546+
static inline void net_stats_update_pkt_tx_timestamp(u8_t tc, u32_t ts)
547+
{
548+
_net_stats_update_pkt_timestamp(&net_stats.ts.tx[tc].time, ts);
549+
}
550+
551+
static inline void net_stats_update_pkt_rx_timestamp(u8_t tc, u32_t ts)
552+
{
553+
_net_stats_update_pkt_timestamp(&net_stats.ts.rx[tc].time, ts);
554+
}
555+
#else
556+
#define net_stats_update_pkt_tx_timestamp(ts)
557+
#define net_stats_update_pkt_rx_timestamp(ts)
558+
#endif /* CONFIG_NET_PKT_TIMESTAMP */
559+
509560
#if defined(CONFIG_NET_STATISTICS_PERIODIC_OUTPUT)
510561
/* A simple periodic statistic printer, used only in net core */
511562
void net_print_statistics_all(void);

0 commit comments

Comments
 (0)