netdev: implement a buffer to log network driver's information

This patch implements a buffer for recording network driver's message. This patch extends below patch to make other network driver use it.

http://marc.info/?l=e1000-devel&m=126690500618157&w=2

When I investigate some network driver's trouble, I feel like I want more detailed debug information, for example, all device register information (like ethtool -d) when device reset was happened or tx/rx ring's move when network stream is not smooth etc.
As a recording measure of such information, there are syslog and ftrace now. but they have some weak points.
Syslog is not appropriate for the size of message is large(ex. recording all register information) or the number of is large(ex.tracing internal move). Ftrace is appropriate for recording such messages.
But ftrace has only one buffer for all ftrace event in kernel. As a result, one adapter's event may be flushed by the others(Of course, syslog has same weak point).

This patch implements a buffer system which beats those weak points.

Features of that are

1.Each interface can hold respective buffer.
It prevents recorded data from being flowed by other's recorded data.

2.An interface can hold multi-buffers.
It makes one adapter have several buffer for each different purpose. For example, one is to trace a driver's internal move, the another is to log error message and some releveant information.

3.resize and on/off per buffer.
if you implement this patch's buffer and you regist buffer in driver's
probe function, all adapter which use that driver must have same size
buffer. If you want trace to one adapter, but not to another, you can make another adapter's buffer off.

The implementation example of igb is patch 2.

HOW TO USE:

If you want to know how to use from driver side, see patch 2. User side is below.

# mount -t debugfs nodev /sys/kernel/debug
# ls /sys/kernel/debug/ndrvbuf
igb-trace-0000:03:00.0 igb-trace-0000:03:00.1
# ls /sys/kernel/debug/ndrvbuf/igb-trace-0000:03:00.0
buffer  buffer_size

"buffer" is output interface. If you set read_format function in register_ndrvbuf, it is used. If not, default read function is used. It displays recorded data by hex style.

# cat buffer
[  1] 50462.369207: clean_tx qidx=1 ntu=154->156
[  0] 50462.369241: clean_rx qidx=0 ntu=111->112
[  0] 50462.369250: xmit qidx=1 ntu=156->158
[  1] 50462.369256: clean_tx qidx=1 ntu=156->158
[  1] 50462.369342: clean_rx qidx=0 ntu=113->114
[  1] 50462.369439: clean_rx qidx=0 ntu=114->115

"buffer_size" is size of buffer per CPU. If you want to change that,

# echo 1000000 > buffer_size
# cat buffer_size
1000000

If you want to disable recording,

# echo 0 > buffer_size

Thanks,
Koki Sanagi.

This patch implements buffer infrastructure under driver/net. This buffer records information from network driver.

---
 drivers/net/Kconfig     |    8 +
 drivers/net/Makefile    |    1 +
 drivers/net/ndrvbuf.c   |  535 +++++++++++++++++++++++++++++++++++++++++++++++
 include/linux/ndrvbuf.h |   57 +++++
 4 files changed, 601 insertions(+), 0 deletions(-)

index 7029cd5..98ac929 100644
@@ -219,6 +219,14 @@ config MII
 	  or internal device.  It is safe to say Y or M here even if your
 	  ethernet card lack MII.
 
+config NDRVBUF
+	tristate "Use buffer for network device driver"
+	default m
+	help
+	  The ndrvbuf is a generally buffer for network driver. It can record
+	  some event or logging informaiton you want to preseve. ring_buffer
+	  is used as a buffer infrastructure.
+
 config MACB
 	tristate "Atmel MACB support"
 	depends on AVR32 || ARCH_AT91SAM9260 || ARCH_AT91SAM9263 || ARCH_AT91SAM9G20 || ARCH_AT91SAM9G45 || ARCH_AT91CAP9

index 4788862..84319ba 100644
@@ -5,6 +5,7 @@
 obj-$(CONFIG_MII) += mii.o
 obj-$(CONFIG_MDIO) += mdio.o
 obj-$(CONFIG_PHYLIB) += phy/
+obj-$(CONFIG_NDRVBUF) += ndrvbuf.o
 
 obj-$(CONFIG_TI_DAVINCI_EMAC) += davinci_emac.o
 

This patch is usage example of previous patch's buffer on igb. The output is like below.

# cat /sys/kernel/debug/ndrvbuf/igb-trace-0000\:03\:00.0/buffer
[  1] 50462.369207: clean_tx qidx=1 ntu=154->156
[  0] 50462.369241: clean_rx qidx=0 ntu=111->112
[  0] 50462.369250: xmit qidx=1 ntu=156->158
[  1] 50462.369256: clean_tx qidx=1 ntu=156->158
[  1] 50462.369342: clean_rx qidx=0 ntu=113->114
[  1] 50462.369439: clean_rx qidx=0 ntu=114->115

This example outputs original print style, because it sets original print function(igb_trace_read) when registered.

register_ndrvbuf(buname, 1000000, igb_trace_read);

If you set NULL to arg3, outputs by ndrvbuf default style.
If you set 0 to size(arg2), recording is disabled at first(but small buffer is alloced).
When you set non-zero to size, recording becomes enabled.

---
 drivers/net/igb/Makefile    |    2 +-
 drivers/net/igb/igb.h       |    1 +
 drivers/net/igb/igb_main.c  |   10 +++++-
 drivers/net/igb/igb_trace.c |   81 +++++++++++++++++++++++++++++++++++++++++++
 drivers/net/igb/igb_trace.h |   21 +++++++++++
 5 files changed, 113 insertions(+), 2 deletions(-)

index 8372cb9..286541e 100644
@@ -33,5 +33,5 @@
 obj-$(CONFIG_IGB) += igb.o
 
 igb-objs := igb_main.o igb_ethtool.o e1000_82575.o \
-	    e1000_mac.o e1000_nvm.o e1000_phy.o e1000_mbx.o
+	    e1000_mac.o e1000_nvm.o e1000_phy.o e1000_mbx.o igb_trace.o
 

index a177570..533c5e6 100644
@@ -315,6 +315,7 @@ struct igb_adapter {
 	unsigned int vfs_allocated_count;
 	struct vf_data_storage *vf_data;
 	u32 rss_queues;
+	struct ndrvbuf *trace;
 };
 
 #define IGB_FLAG_HAS_MSI           (1 << 0)

index 583a21c..f754fd1 100644
@@ -48,6 +48,7 @@
 #include <linux/dca.h>
 #endif
 #include "igb.h"
+#include "igb_trace.h"
 
 #define DRV_VERSION "2.1.0-k2"
 char igb_driver_name[] = "igb";

@@ -1412,6 +1413,7 @@ static int __devinit igb_probe(struct pci_dev *pdev,
 	int err, pci_using_dac;
 	u16 eeprom_apme_mask = IGB_EEPROM_APME;
 	u32 part_num;
+	char bufname[NDRVBUF_NAME_SIZE];
 
 	err = pci_enable_device_mem(pdev);
 	if (err)

@@ -1674,6 +1676,8 @@ static int __devinit igb_probe(struct pci_dev *pdev,
 		(adapter->flags & IGB_FLAG_HAS_MSI) ? "MSI" : "legacy",
 		adapter->num_rx_queues, adapter->num_tx_queues);
 
+	sprintf(bufname, "igb-trace-%s", pci_name(pdev));
+	adapter->trace = register_ndrvbuf(bufname, 1000000, igb_trace_read);
 	return 0;
 
 err_register:

@@ -1734,6 +1738,7 @@ static void __devexit igb_remove(struct pci_dev *pdev)
 	 * would have already happened in close and is redundant. */
 	igb_release_hw_control(adapter);
 
+	unregister_ndrvbuf(adapter->trace);
 	unregister_netdev(netdev);
 
 	igb_clear_interrupt_scheme(adapter);

@@ -3814,6 +3819,7 @@ netdev_tx_t igb_xmit_frame_ring_adv(struct sk_buff *skb,
 	}
 
 	igb_tx_queue_adv(tx_ring, tx_flags, count, skb->len, hdr_len);
+	igb_trace_write_xmit(adapter->trace, tx_ring, first);
 
 	/* Make sure there is space in the ring for the next send. */
 	igb_maybe_stop_tx(tx_ring, MAX_SKB_FRAGS + 4);

@@ -5039,7 +5045,7 @@ static bool igb_clean_tx_irq(struct igb_q_vector *q_vector)
 		eop = tx_ring->buffer_info[i].next_to_watch;
 		eop_desc = E1000_TX_DESC_ADV(*tx_ring, eop);
 	}
-
+	igb_trace_write_clean_tx(adapter->trace, tx_ring, i);
 	tx_ring->next_to_clean = i;
 
 	if (unlikely(count &&

@@ -5195,6 +5201,7 @@ static bool igb_clean_rx_irq_adv(struct igb_q_vector *q_vector,
 {
 	struct igb_ring *rx_ring = q_vector->rx_ring;
 	struct net_device *netdev = rx_ring->netdev;
+	struct igb_adapter *adapter = netdev_priv(netdev);
 	struct pci_dev *pdev = rx_ring->pdev;
 	union e1000_adv_rx_desc *rx_desc , *next_rxd;
 	struct igb_buffer *buffer_info , *next_buffer;

@@ -5309,6 +5316,7 @@ next_desc:
 		staterr = le32_to_cpu(rx_desc->wb.upper.status_error);
 	}
 
+	igb_trace_write_clean_rx(adapter->trace, rx_ring, i);
 	rx_ring->next_to_clean = i;
 	cleaned_count = igb_desc_unused(rx_ring);
 

new file mode 100644
index 0000000..fa130e1
@@ -0,0 +1,21 @@
+#ifndef _IGB_TRACE_H_
+#define _IGB_TRACE_H_
+
+#include <linux/ndrvbuf.h>
+#include "igb.h"
+
+#define IGB_TRACE_EVENT_XMIT		0x01
+#define IGB_TRACE_EVENT_CLEAN_TX	0x02
+#define IGB_TRACE_EVENT_CLEAN_RX	0x03
+
+extern void igb_trace_write_xmit(struct ndrvbuf *ndrvbuf,
+			struct igb_ring *tx_ring, int i);
+extern void igb_trace_write_clean_tx(struct ndrvbuf *ndrvbuf,
+			struct igb_ring *tx_ring, int i);
+extern void igb_trace_write_clean_rx(struct ndrvbuf *ndrvbuf,
+			struct igb_ring *rx_ring, int i);
+
+extern size_t igb_trace_read(void *ubuf, size_t bufsize, void *entry,
+			size_t size, int cpu, u64 ts);
+
+#endif /*_IGB_TRACE_H_*/

This depends on NDRVBUF, yet I see no Kconfig change in this patch.

Wow, 600 lines... thats what I call bloat...

Why no use a very simple interface (printk like) ?

xxx_printf(dev->trace, "xmit qidx=%u ntu=%d->%d\n",

	   tx_ring->queue_index, first, tx_ring->next_to_use);

Anyway, this has nothing to do with network drivers and should be discussed on lkml.

From: Eric Dumazet <[email protected]>
Date: Mon, 05 Apr 2010 10:42:26 +0200

And we have all sorts of facilities for creating filesystem streams and ring buffers of debug information.

You could even hook into 'perf' to log and process these events in probably like 12 lines of code.

I'm still having a hard time understanding why this approach is preferable to the previous approach you took using tracepoints. Granted you can't get driver internal state as easily, but its generic and doesn't do...this. Neil

This igb can exist without ndrvbuf.
If ndrvbuf modules is not loaded, igb operates originally. So this doesn't depend on ndrvbuf.

We can get below information with this patch

1. Driver operates normaly or not
2. Tx ring's state

About 1, the preivous approach meets, but about 2, some hooks need in driver code like this patch. If we get it, it is available to solute "Tx Unit Hung" message. This message indicates that tx descriptor ring's process is not smooth. When a countermeasure was taken to system that outputs "Tx Unit Hung" message, this state information is available to evaluate a countermeasure. But what you say is true, this patch is not generic.
it may be good to rebase the previous approach to focus on 1.
And it is better to consider separately about 2.