IrDA spams logfiles - since 2.6.19

IrDA spams logfiles - since 2.6.19

[Andreas Leitgeb]

I'm not on this list, so please keep me CC'ed on this thread.

Since 2.6.19 I've got a problem with my Tekram IRmate 410U 
usb-irda-dongle. Until 2.6.18.3 (the latest I had before 2.6.19*)
it worked just fine.  2.6.19.1 had another change in irda-usb
but that didn't solve the problem.

As soon as I load the irda-usb module with the device plugged,
I get lots of messages of following kind into the logs:
  irda_usb_hard_xmit(), Insuficient skb headroom.
(the "Insuficient"-typo is original)
about 7 in a second, then a 2-secs pause. Repeating 
until the irda-usb module is removed again.

I then looked up the kernel-source for that particular 
typo'ed word, and added some info to the log:
  drivers/net/irda/irda-usb.c:448:
        if (skb_headroom(skb) < self->header_length) {
                IRDA_DEBUG(0, "%s(), Insuficient skb headroom. %d / %d \n",
                     __FUNCTION__, skb_headroom(skb) , self->header_length);
        ...
Which came out as:
  irda_usb_hard_xmit(), Insuficient skb headroom. 0 / 1
Thus, while self->header_length == USB_IRDA_HEADER,
I didn't yet understand the meaning of fields
  ->data and ->head of the skb.

I don't know, if the warning itself is right or wrong,
because other than the spamming of logs, transferring
data over irda appears to work just fine.

(I've got timestamps turned on, so usual repeat-compression
by syslogd doesn't take effect.)

Re: IrDA spams logfiles - since 2.6.19

[David Miller]

From: Andreas Leitgeb <avl@logic.at>
Date: Sun, 7 Jan 2007 01:51:50 +0100

> As soon as I load the irda-usb module with the device plugged,
> I get lots of messages of following kind into the logs:
>   irda_usb_hard_xmit(), Insuficient skb headroom.
> (the "Insuficient"-typo is original)
> about 7 in a second, then a 2-secs pause. Repeating 
> until the irda-usb module is removed again.
> 
> I then looked up the kernel-source for that particular 
> typo'ed word, and added some info to the log:
>   drivers/net/irda/irda-usb.c:448:
>         if (skb_headroom(skb) < self->header_length) {
>                 IRDA_DEBUG(0, "%s(), Insuficient skb headroom. %d / %d \n",
>                      __FUNCTION__, skb_headroom(skb) , self->header_length);
>         ...
> Which came out as:
>   irda_usb_hard_xmit(), Insuficient skb headroom. 0 / 1
> Thus, while self->header_length == USB_IRDA_HEADER,
> I didn't yet understand the meaning of fields
>   ->data and ->head of the skb.
> 
> I don't know, if the warning itself is right or wrong,
> because other than the spamming of logs, transferring
> data over irda appears to work just fine.

The warning is a bit extreme because the skb_cow() call does fix
things up and makes space available.

But it's not the most efficient thing in the world, so it's good
that we know about this so we can have a closer work.

I want to remove that warning, but first let's figure out what the
call chain is that causes skb_headroom() to end up being zero.

Can you get us some logs this debugging patch?  Thanks.

Please make sure CONFIG_BUG is enabled in your kernel config.
You should get a stack backtrace in your logs when the event
happens.

diff --git a/drivers/net/irda/irda-usb.c b/drivers/net/irda/irda-usb.c
index 3ca1082..2017024 100644
--- a/drivers/net/irda/irda-usb.c
+++ b/drivers/net/irda/irda-usb.c
@@ -446,7 +446,7 @@ static int irda_usb_hard_xmit(struct sk_buff *skb, struct net_device *netdev)
 	 * Also, we don't use directly skb_cow(), because it require
 	 * headroom >= 16, which force unnecessary copies - Jean II */
 	if (skb_headroom(skb) < self->header_length) {
-		IRDA_DEBUG(0, "%s(), Insuficient skb headroom.\n", __FUNCTION__);
+		WARN_ON(1);
 		if (skb_cow(skb, self->header_length)) {
 			IRDA_WARNING("%s(), failed skb_cow() !!!\n", __FUNCTION__);
 			goto drop;

Re: IrDA spams logfiles - since 2.6.19

[Samuel Ortiz]

Hi Dave,

On Wed, Jan 10, 2007 at 03:26:07PM -0800, David Miller wrote:
> The warning is a bit extreme because the skb_cow() call does fix
> things up and makes space available.
> 
> But it's not the most efficient thing in the world, so it's good
> that we know about this so we can have a closer work.
> 
> I want to remove that warning, but first let's figure out what the
> call chain is that causes skb_headroom() to end up being zero.
In Andreas case, the device is probably in discovery mode, sending IrDA
discovery frames periodically. For each of them, the path is the following:
irlap_slot_timer_expired()
  irlap_do_event()
    irlap_state_query()
      irlap_send_discovery_xid_frame()
        dev_hard_start_xmit()
          irda_usb_hard_xmit()

irlap_send_discovery_xid_frame() is the one allocating and building the
discovery frame. It is an IrLAP frame.
As you might remember, this routine used to call dev_alloc_skb() for 
allocation but now calls alloc_skb(). So, it used to reserve a 16 bytes
header, while now it doesn't.
The issue here is that the USB-IrDA specification tells us that we have to add
a 1 byte header to the IrLAP frame (and this becomes 3 bytes for some devices
playing with the spec) before pushing it to the USB bus.
So, while the discovery routine returns a correct IrLAP skb, with no headroom,
the irda-usb code needs to add a 1 (or 3) bytes header to it.

One solution to fix that problem could be to systematically add a header for
every allocated IrLAP frame on the IrDA TX path. Since the USB-IrDA spec is
defined by the USB-IF, not by the IrDA, I don't really like this solution. It
would create code changes all over the IrDA stack only for handling the
USB-IrDA case.
The second solution would consist of copying the skb->data into some irda-usb.c
pre-allocated buffer, instead of always calling skb_cow(). That would save us
one kmalloc(). Obviously, there is a performance hit as we're doing one memcpy
for each and every packet sent. I think this is a cleaner solution but the
performance hit must be taken to account since the IrDA USB dongles are among
the most popular IrDA devices.

Dave, please let me know what you think about it, and if you agree with my
problem description, please let me know which solution you would advice for.

The patch for the second solution would look something like that (although
I could use some of the skb routines - skb_copy_bits() - to copy the skb
data). It's been tested with my USB stir4220 based IrDA dongle:

diff --git a/drivers/net/irda/irda-usb.h b/drivers/net/irda/irda-usb.h
index 6b2271f..e846c38 100644
--- a/drivers/net/irda/irda-usb.h
+++ b/drivers/net/irda/irda-usb.h
@@ -156,6 +156,7 @@ struct irda_usb_cb {
 	struct irlap_cb   *irlap;	/* The link layer we are binded to */
 	struct qos_info qos;
 	char *speed_buff;		/* Buffer for speed changes */
+	char *tx_buff;
 
 	struct timeval stamp;
 	struct timeval now;
diff --git a/drivers/net/irda/irda-usb.c b/drivers/net/irda/irda-usb.c
index 3ca1082..5f22a8e 100644
--- a/drivers/net/irda/irda-usb.c
+++ b/drivers/net/irda/irda-usb.c
@@ -441,25 +441,14 @@ static int irda_usb_hard_xmit(struct sk_buff *skb, struct net_device *netdev)
 		goto drop;
 	}
 
-	/* Make sure there is room for IrDA-USB header. The actual
-	 * allocation will be done lower in skb_push().
-	 * Also, we don't use directly skb_cow(), because it require
-	 * headroom >= 16, which force unnecessary copies - Jean II */
-	if (skb_headroom(skb) < self->header_length) {
-		IRDA_DEBUG(0, "%s(), Insuficient skb headroom.\n", __FUNCTION__);
-		if (skb_cow(skb, self->header_length)) {
-			IRDA_WARNING("%s(), failed skb_cow() !!!\n", __FUNCTION__);
-			goto drop;
-		}
-	}
+	memset(self->tx_buff, 0, IRDA_SKB_MAX_MTU + self->header_length);
+	memcpy(self->tx_buff + self->header_length, skb->data, skb->len);
 
 	/* Change setting for next frame */
-
 	if (self->capability & IUC_STIR421X) {
 		__u8 turnaround_time;
-		__u8* frame;
+		__u8* frame = self->tx_buff;
 		turnaround_time = get_turnaround_time( skb );
-		frame= skb_push(skb, self->header_length);
 		irda_usb_build_header(self, frame, 0);
 		frame[2] = turnaround_time;
 		if ((skb->len != 0) &&
@@ -472,17 +461,18 @@ static int irda_usb_hard_xmit(struct sk_buff *skb, struct net_device *netdev)
 			frame[1] = 0;
 		}
 	} else {
-		irda_usb_build_header(self, skb_push(skb, self->header_length), 0);
+		irda_usb_build_header(self, self->tx_buff, 0);
 	}
 
 	/* FIXME: Make macro out of this one */
 	((struct irda_skb_cb *)skb->cb)->context = self;
 
-        usb_fill_bulk_urb(urb, self->usbdev, 
+	usb_fill_bulk_urb(urb, self->usbdev, 
 		      usb_sndbulkpipe(self->usbdev, self->bulk_out_ep),
-                      skb->data, IRDA_SKB_MAX_MTU,
+                      self->tx_buff, IRDA_SKB_MAX_MTU + self->header_length,
                       write_bulk_callback, skb);
-	urb->transfer_buffer_length = skb->len;
+	urb->transfer_buffer_length = skb->len + self->header_length;
+
 	/* This flag (URB_ZERO_PACKET) indicates that what we send is not
 	 * a continuous stream of data but separate packets.
 	 * In this case, the USB layer will insert an empty USB frame (TD)
@@ -1455,6 +1445,9 @@ static inline void irda_usb_close(struct irda_usb_cb *self)
 	/* Remove the speed buffer */
 	kfree(self->speed_buff);
 	self->speed_buff = NULL;
+
+	kfree(self->tx_buff);
+	self->tx_buff = NULL;
 }
 
 /********************** USB CONFIG SUBROUTINES **********************/
@@ -1753,9 +1746,14 @@ static int irda_usb_probe(struct usb_interface *intf,
 
 	memset(self->speed_buff, 0, IRDA_USB_SPEED_MTU);
 
+	self->tx_buff = kzalloc(IRDA_SKB_MAX_MTU + self->header_length,
+				GFP_KERNEL);
+	if (self->tx_buff == NULL) 
+		goto err_out_4;
+
 	ret = irda_usb_open(self);
 	if (ret) 
-		goto err_out_4;
+		goto err_out_5;
 
 	IRDA_MESSAGE("IrDA: Registered device %s\n", net->name);
 	usb_set_intfdata(intf, self);
@@ -1766,14 +1764,14 @@ static int irda_usb_probe(struct usb_interface *intf,
 		self->needspatch = (ret < 0);
 		if (self->needspatch) {
 			IRDA_ERROR("STIR421X: Couldn't upload patch\n");
-			goto err_out_5;
+			goto err_out_6;
 		}
 
 		/* replace IrDA class descriptor with what patched device is now reporting */
 		irda_desc = irda_usb_find_class_desc (self->usbintf);
 		if (irda_desc == NULL) {
 			ret = -ENODEV;
-			goto err_out_5;
+			goto err_out_6;
 		}
 		if (self->irda_desc)
 			kfree (self->irda_desc);
@@ -1782,9 +1780,10 @@ static int irda_usb_probe(struct usb_interface *intf,
 	}
 
 	return 0;
-
-err_out_5:
+err_out_6:
 	unregister_netdev(self->netdev);
+err_out_5:
+	kfree(self->tx_buff);
 err_out_4:
 	kfree(self->speed_buff);
 err_out_3:
 

[PATCH 1/2] [IrDA] irda-usb TX path optimization (was Re: IrDA spams logfiles - since 2.6.19)

[Samuel Ortiz]

Hi Dave,

Since we stop using dev_alloc_skb on the IrDA TX frame, we constantly run
into the case of the skb headroom being 0, and thus we call skb_cow for
every IrDA TX frame.
This patch uses a local buffer and memcpy the skb to it, saving us a
kmalloc for each of those IrDA TX frames.

Signed-off-by: Samuel Ortiz <samuel@sortiz.org>

---
 drivers/net/irda/irda-usb.c |   43 ++++++++++++++++++++-----------------------
 drivers/net/irda/irda-usb.h |    1 +
 2 files changed, 21 insertions(+), 23 deletions(-)

diff --git a/drivers/net/irda/irda-usb.c b/drivers/net/irda/irda-usb.c
index 3ca1082..8381c04 100644
--- a/drivers/net/irda/irda-usb.c
+++ b/drivers/net/irda/irda-usb.c
@@ -441,25 +441,13 @@ static int irda_usb_hard_xmit(struct sk_buff *skb, struct net_device *netdev)
 		goto drop;
 	}
 
-	/* Make sure there is room for IrDA-USB header. The actual
-	 * allocation will be done lower in skb_push().
-	 * Also, we don't use directly skb_cow(), because it require
-	 * headroom >= 16, which force unnecessary copies - Jean II */
-	if (skb_headroom(skb) < self->header_length) {
-		IRDA_DEBUG(0, "%s(), Insuficient skb headroom.\n", __FUNCTION__);
-		if (skb_cow(skb, self->header_length)) {
-			IRDA_WARNING("%s(), failed skb_cow() !!!\n", __FUNCTION__);
-			goto drop;
-		}
-	}
+	memcpy(self->tx_buff + self->header_length, skb->data, skb->len);
 
 	/* Change setting for next frame */
-
 	if (self->capability & IUC_STIR421X) {
 		__u8 turnaround_time;
-		__u8* frame;
+		__u8* frame = self->tx_buff;
 		turnaround_time = get_turnaround_time( skb );
-		frame= skb_push(skb, self->header_length);
 		irda_usb_build_header(self, frame, 0);
 		frame[2] = turnaround_time;
 		if ((skb->len != 0) &&
@@ -472,17 +460,17 @@ static int irda_usb_hard_xmit(struct sk_buff *skb, struct net_device *netdev)
 			frame[1] = 0;
 		}
 	} else {
-		irda_usb_build_header(self, skb_push(skb, self->header_length), 0);
+		irda_usb_build_header(self, self->tx_buff, 0);
 	}
 
 	/* FIXME: Make macro out of this one */
 	((struct irda_skb_cb *)skb->cb)->context = self;
 
-        usb_fill_bulk_urb(urb, self->usbdev, 
+	usb_fill_bulk_urb(urb, self->usbdev,
 		      usb_sndbulkpipe(self->usbdev, self->bulk_out_ep),
-                      skb->data, IRDA_SKB_MAX_MTU,
+                      self->tx_buff, skb->len + self->header_length,
                       write_bulk_callback, skb);
-	urb->transfer_buffer_length = skb->len;
+
 	/* This flag (URB_ZERO_PACKET) indicates that what we send is not
 	 * a continuous stream of data but separate packets.
 	 * In this case, the USB layer will insert an empty USB frame (TD)
@@ -1455,6 +1443,9 @@ static inline void irda_usb_close(struct irda_usb_cb *self)
 	/* Remove the speed buffer */
 	kfree(self->speed_buff);
 	self->speed_buff = NULL;
+
+	kfree(self->tx_buff);
+	self->tx_buff = NULL;
 }
 
 /********************** USB CONFIG SUBROUTINES **********************/
@@ -1753,9 +1744,14 @@ static int irda_usb_probe(struct usb_interface *intf,
 
 	memset(self->speed_buff, 0, IRDA_USB_SPEED_MTU);
 
+	self->tx_buff = kzalloc(IRDA_SKB_MAX_MTU + self->header_length,
+				GFP_KERNEL);
+	if (self->tx_buff == NULL)
+		goto err_out_4;
+
 	ret = irda_usb_open(self);
 	if (ret) 
-		goto err_out_4;
+		goto err_out_5;
 
 	IRDA_MESSAGE("IrDA: Registered device %s\n", net->name);
 	usb_set_intfdata(intf, self);
@@ -1766,14 +1762,14 @@ static int irda_usb_probe(struct usb_interface *intf,
 		self->needspatch = (ret < 0);
 		if (self->needspatch) {
 			IRDA_ERROR("STIR421X: Couldn't upload patch\n");
-			goto err_out_5;
+			goto err_out_6;
 		}
 
 		/* replace IrDA class descriptor with what patched device is now reporting */
 		irda_desc = irda_usb_find_class_desc (self->usbintf);
 		if (irda_desc == NULL) {
 			ret = -ENODEV;
-			goto err_out_5;
+			goto err_out_6;
 		}
 		if (self->irda_desc)
 			kfree (self->irda_desc);
@@ -1782,9 +1778,10 @@ static int irda_usb_probe(struct usb_interface *intf,
 	}
 
 	return 0;
-
-err_out_5:
+err_out_6:
 	unregister_netdev(self->netdev);
+err_out_5:
+	kfree(self->tx_buff);
 err_out_4:
 	kfree(self->speed_buff);
 err_out_3:
diff --git a/drivers/net/irda/irda-usb.h b/drivers/net/irda/irda-usb.h
index 6b2271f..e846c38 100644
--- a/drivers/net/irda/irda-usb.h
+++ b/drivers/net/irda/irda-usb.h
@@ -156,6 +156,7 @@ struct irda_usb_cb {
 	struct irlap_cb   *irlap;	/* The link layer we are binded to */
 	struct qos_info qos;
 	char *speed_buff;		/* Buffer for speed changes */
+	char *tx_buff;
 
 	struct timeval stamp;
 	struct timeval now;
-- 
1.4.4.4

Re: [PATCH 1/2] [IrDA] irda-usb TX path optimization

[David Miller]

From: Samuel Ortiz <samuel@sortiz.org>
Date: Mon, 15 Jan 2007 11:15:11 +0200

> Since we stop using dev_alloc_skb on the IrDA TX frame, we constantly run
> into the case of the skb headroom being 0, and thus we call skb_cow for
> every IrDA TX frame.
> This patch uses a local buffer and memcpy the skb to it, saving us a
> kmalloc for each of those IrDA TX frames.
> 
> Signed-off-by: Samuel Ortiz <samuel@sortiz.org>

Applied, thanks.

Technically this is a bug fix too because once an SKB hits the
transmit function it should essentially be immutable, ie. you
shouldn't be writing to it.  tcpdump sniffers could be looking
at the SKB, as one example.

Re: [PATCH 1/2] [IrDA] irda-usb TX path optimization

[Herbert Xu]

David Miller <davem@davemloft.net> wrote:
> 
> Technically this is a bug fix too because once an SKB hits the
> transmit function it should essentially be immutable, ie. you
> shouldn't be writing to it.  tcpdump sniffers could be looking
> at the SKB, as one example.

We do have a way around that with skb_header_cloned.  In fact
it looks like VLAN should use it as otherwise TCP packets will
get copied unnecessarily.

This is still not optimal for AF_PACKET users since they will
still cause things like VLANs to do the copy even when it isn't
necessary because it doesn't touch any part of the packet that
AF_PACKET actually looks at.

Cheers,
-- 
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt