Re: [B.A.T.M.A.N.] [PATCHv3] batman-adv: Limit queue lengths for batman and broadcast packets

["Linus Lüssing" <linus.luessing@web.de>]

[-- Attachment #1: Type: text/plain, Size: 15190 bytes --]

Okay, this third version seems to get rid of the nasty OOMs very
well and after stopping the ping-broadcast on Node A in a setup of
A - B - C, the broadcast storm stops nearly immediately.

However, in my VM setup (no matter if qemu or kvm) I'm getting a
soft-lockup on B. After about 10 seconds I'm not able to send any
commands to B via ssh or via a serial console. But if I stop the
ping broadcast flood, B suddenly receives the input I've been
sending minutes before during the broadcast.

The kernel is outputting the following trace after 60 seconds of
soft-lockup:
--------------------------------------------------------------
mesh-node@mesh-node1:~$ uptime
 08:37:11 up 57 min,  2 users,  load average: 4.38, 4.40, 3.30
mesh-node@mesh-node1:~$ uptime
 08:37:12 up 57 min,  2 users,  load average: 4.38, 4.40, 3.30
mesh-node@mesh-node1:~$ uptime[ 3508.988304] BUG: soft lockup - CPU#0 stuck for 61s! [bat_events:3034]
[ 3508.988304] Modules linked in: batman_adv ipv6 loop button psmouse parport_pc parport i2c_piix4 i2c_core snd_pcsp serio_raw snd_pcm snd_timer snd e1000 soundcore snd_page_alloc evdev floppy ext3 jbd mbcache ide_cd_mod cdrom thermal processor fan thermal_sys ide_disk ide_pci_generic piix ide_core ata_generic libata scsi_mod dock [last unloaded: batman_adv]
[ 3508.988304]
[ 3508.988304] Pid: 3034, comm: bat_events Not tainted (2.6.26-2-686 #1)
[ 3508.988304] EIP: 0060:[<d091bc11>] EFLAGS: 00000286 CPU: 0
[ 3508.988304] EIP is at e1000_clean_tx_irq+0xfc/0x263 [e1000]
[ 3508.988304] EAX: 0000009c EBX: 0000009c ECX: 0000f601 EDX: cf23bba0
[ 3508.988304] ESI: cf23bba0 EDI: cfb5d3e0 EBP: cf3019c0 ESP: cf93bef0
[ 3508.988304]  DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 3508.988304] CR0: 8005003b CR2: 081eb008 CR3: 0f3d1000 CR4: 00000690
[ 3508.988304] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 3508.988304] DR6: 00000000 DR7: 00000000
[ 3508.988304]  [<d091e752>] ? e1000_clean+0x3c/0x216 [e1000]
[ 3508.988304]  [<c025a8af>] ? net_rx_action+0x9c/0x1b9
[ 3508.988304]  [<c0126629>] ? __do_softirq+0x66/0xd3
[ 3508.988304]  [<c01266db>] ? do_softirq+0x45/0x53
[ 3508.988304]  [<c0126912>] ? local_bh_enable+0x66/0x71
[ 3508.988304]  [<c025b279>] ? dev_queue_xmit+0x287/0x2be
[ 3508.988304]  [<d09b52bf>] ? send_outstanding_bcast_packet+0x0/0xa5 [batman_adv]
[ 3508.988304]  [<d09b531e>] ? send_outstanding_bcast_packet+0x5f/0xa5 [batman_adv]
[ 3508.988304]  [<c012f03e>] ? run_workqueue+0x74/0xf2
[ 3508.988304]  [<c012f719>] ? worker_thread+0x0/0xbd
[ 3508.988304]  [<c012f7cc>] ? worker_thread+0xb3/0xbd
[ 3508.988304]  [<c01319d4>] ? autoremove_wake_function+0x0/0x2d
[ 3508.988304]  [<c0131913>] ? kthread+0x38/0x5d
[ 3508.988304]  [<c01318db>] ? kthread+0x0/0x5d
[ 3508.988304]  [<c01044f7>] ? kernel_thread_helper+0x7/0x10
[ 3508.988304]  =======================

 08:38:55 up 59 min,  2 users,  load average: 8.59, 5.64, 3.84
mesh-node@mesh-node1:~$
mesh-node@mesh-node1:~$
mesh-node@mesh-node1:~$
--------------------------------------------------------------

I'm not sure yet, whether the issue is just that
send_broadcast_packet() is being called so often (~7000 times/
second) or if it is locking something somewhere for too long or
both.

I tried to investigate a little further what might take most of
the time send_outstanding_packets(). There I noticed, that at this
high burden send_skb_packet() in send_outstanding_packets() needs
most of the time: ~12 times (of ~7000) it needs more then 20ms
(~80ms usually) during one second. So those ~12 strange times are
holding the rcu_lock for 99% of the time on node B. Could this be
the cause for the soft-lockups? what is still confusing me is, if
it's send_skb_packet() and not send_outstanding_packets() itself
that takes so long, why isn't send_skb_packet() showing up in the
trace?

I've been using the following patch for the measurments on top of
rev 1616 + Simon's seqno patch v2 + Simon's limit patch v3:

--------------------------------------------------------------
--- a/batman-adv-kernelland/send.c
+++ b/batman-adv-kernelland/send.c
@@ -431,6 +431,7 @@ int add_bcast_packet_to_list(struct sk_buff *skb)

 void send_outstanding_bcast_packet(struct work_struct *work)
 {
+unsigned long start, timespent;
        struct batman_if *batman_if;
        struct delayed_work *delayed_work =
                container_of(work, struct delayed_work, work);
@@ -449,8 +450,15 @@ void send_outstanding_bcast_packet(struct work_struct *work)
                /* send a copy of the saved skb */
                skb1 = skb_copy(forw_packet->skb, GFP_ATOMIC);
                if (skb1)
+{
+start = jiffies;
                        send_skb_packet(skb1,
                                batman_if, broadcastAddr);
+timespent = jiffies - start;
+if(printk_ratelimit() || timespent > 5) {
+printk("Took %d jiffies (%d ms)\n", timespent, (timespent*1000)/HZ);
+}
+}
        }
        rcu_read_unlock();

--------------------------------------------------------------

The resulting output on node B is the following:
(hmm, okay, in this output it's about 8, not 12 times per second as it
had been in previous tests)
--------------------------------------------------------------
[ 4164.437463] Took 19 jiffies (76 ms)
[ 4164.552022] Took 22 jiffies (88 ms)
[ 4164.654244] Took 20 jiffies (80 ms)
[ 4164.758564] Took 20 jiffies (80 ms)
[ 4164.858450] Took 19 jiffies (76 ms)
[ 4164.962935] Took 22 jiffies (88 ms)
[ 4165.067755] Took 19 jiffies (76 ms)
[ 4165.172166] Took 23 jiffies (92 ms)
[ 4165.276810] Took 19 jiffies (76 ms)
[ 4165.381937] Took 19 jiffies (76 ms)
[ 4165.487952] Took 18 jiffies (72 ms)
[ 4165.591722] Took 19 jiffies (76 ms)
[ 4165.696384] Took 19 jiffies (76 ms)
[ 4165.800138] Took 19 jiffies (76 ms)
[ 4165.903559] Took 19 jiffies (76 ms)
[ 4166.007544] Took 22 jiffies (88 ms)
[ 4166.116471] Took 20 jiffies (80 ms)
[ 4169.372036] __ratelimit: 9633 messages suppressed
[ 4169.372036] Took 1 jiffies (4 ms)
[ 4169.452787] Took 20 jiffies (80 ms)
[ 4169.558822] Took 21 jiffies (84 ms)
[ 4169.662983] Took 20 jiffies (80 ms)
[ 4171.180022] Took 6 jiffies (24 ms)
[ 4171.281675] Took 20 jiffies (80 ms)
[ 4171.387203] Took 20 jiffies (80 ms)
[ 4171.486460] Took 19 jiffies (76 ms)
[ 4174.370508] __ratelimit: 12882 messages suppressed
[ 4174.372021] Took 1 jiffies (4 ms)
[ 4174.460143] Took 21 jiffies (84 ms)
[ 4174.564234] Took 23 jiffies (92 ms)
[ 4174.668185] Took 19 jiffies (76 ms)
[ 4174.772064] Took 19 jiffies (76 ms)
[ 4174.876539] Took 18 jiffies (72 ms)
[ 4174.984752] Took 23 jiffies (92 ms)
[ 4175.088186] Took 20 jiffies (80 ms)
[ 4175.200019] Took 21 jiffies (84 ms)
[ 4175.300615] Took 20 jiffies (80 ms)
[ 4175.404180] Took 20 jiffies (80 ms)
[ 4175.506979] Took 21 jiffies (84 ms)
[ 4175.611148] Took 21 jiffies (84 ms)
[ 4175.712018] Took 19 jiffies (76 ms)
[ 4175.816150] Took 22 jiffies (88 ms)
[ 4175.921259] Took 19 jiffies (76 ms)
[ 4176.026627] Took 20 jiffies (80 ms)
[ 4176.135124] Took 20 jiffies (80 ms)
[ 4176.243757] Took 21 jiffies (84 ms)
[ 4176.349231] Took 21 jiffies (84 ms)
[ 4176.444639] Took 18 jiffies (72 ms)
[ 4176.543197] Took 18 jiffies (72 ms)
[ 4176.643360] Took 18 jiffies (72 ms)
[ 4176.741147] Took 17 jiffies (68 ms)
[ 4176.840095] Took 18 jiffies (72 ms)
[ 4176.938419] Took 18 jiffies (72 ms)
[ 4177.036107] Took 17 jiffies (68 ms)
[ 4177.139641] Took 18 jiffies (72 ms)
--------------------------------------------------------------

Cheers, Linus


On Wed, Apr 07, 2010 at 10:11:23AM +0200, Simon Wunderlich wrote:
> This patch limits the queue lengths of batman and broadcast packets. BATMAN
> packets are held back for aggregation and jittered to avoid interferences.
> Broadcast packets are stored to be sent out multiple times to increase
> the probability to be received by other nodes in lossy environments.
> 
> Especially in extreme cases like broadcast storms, the queues have been seen
> to run full, eating up all the memory and triggering the infamous OOM killer.
> With the queue length limits introduced in this patch, this problem is
> avoided.
> 
> Each queue is limited to 256 entries for now, resulting in 1 MB of maximum
> space available in total for typical setups (assuming one packet including
> overhead does not require more than 2000 byte). This should also be reasonable
> for smaller routers, otherwise the defines can be tweaked later.
> 
> This third version of the patch does not increase the local broadcast 
> sequence number when the queue is already full.
> 
> Signed-off-by: Simon Wunderlich <siwu@hrz.tu-chemnitz.de>
> ---
> Index: a/batman-adv-kernelland/send.c
> ===================================================================
> --- a/batman-adv-kernelland/send.c	(revision 1616)
> +++ a/batman-adv-kernelland/send.c	(working copy)
> @@ -378,18 +378,35 @@
>  			   send_time);
>  }
>  
> -void add_bcast_packet_to_list(struct sk_buff *skb)
> +#define atomic_dec_not_zero(v)          atomic_add_unless((v), -1, 0)
> +/* add a broadcast packet to the queue and setup timers. broadcast packets
> + * are sent multiple times to increase probability for beeing received.
> + *
> + * This function returns NETDEV_TX_OK on success and NETDEV_TX_BUSY on
> + * errors.
> + *
> + * The skb is not consumed, so the caller should make sure that the
> + * skb is freed. */
> +int add_bcast_packet_to_list(struct sk_buff *skb)
>  {
>  	struct forw_packet *forw_packet;
>  
> +	if (!atomic_dec_not_zero(&bcast_queue_left)) {
> +		bat_dbg(DBG_BATMAN, "bcast packet queue full\n");
> +		return NETDEV_TX_BUSY;
> +	}
> +
>  	forw_packet = kmalloc(sizeof(struct forw_packet), GFP_ATOMIC);
> -	if (!forw_packet)
> -		return;
> +	if (!forw_packet) {
> +		atomic_inc(&bcast_queue_left);
> +		return NETDEV_TX_BUSY;
> +	}
>  
>  	skb = skb_copy(skb, GFP_ATOMIC);
>  	if (!skb) {
> +		atomic_inc(&bcast_queue_left);
>  		kfree(forw_packet);
> -		return;
> +		return NETDEV_TX_BUSY;
>  	}
>  
>  	skb_reset_mac_header(skb);
> @@ -401,6 +418,7 @@
>  	forw_packet->num_packets = 0;
>  
>  	_add_bcast_packet_to_list(forw_packet, 1);
> +	return NETDEV_TX_OK;
>  }
>  
>  void send_outstanding_bcast_packet(struct work_struct *work)
> @@ -435,8 +453,10 @@
>  	if ((forw_packet->num_packets < 3) &&
>  	    (atomic_read(&module_state) != MODULE_DEACTIVATING))
>  		_add_bcast_packet_to_list(forw_packet, ((5 * HZ) / 1000));
> -	else
> +	else {
>  		forw_packet_free(forw_packet);
> +		atomic_inc(&bcast_queue_left);
> +	}
>  }
>  
>  void send_outstanding_bat_packet(struct work_struct *work)
> @@ -462,6 +482,10 @@
>  	    (atomic_read(&module_state) != MODULE_DEACTIVATING))
>  		schedule_own_packet(forw_packet->if_incoming);
>  
> +	/* don't count own packet */
> +	if (!forw_packet->own)
> +		atomic_inc(&batman_queue_left);
> +
>  	forw_packet_free(forw_packet);
>  }
>  
> Index: a/batman-adv-kernelland/send.h
> ===================================================================
> --- a/batman-adv-kernelland/send.h	(revision 1616)
> +++ a/batman-adv-kernelland/send.h	(working copy)
> @@ -33,7 +33,7 @@
>  			     struct batman_packet *batman_packet,
>  			     uint8_t directlink, int hna_buff_len,
>  			     struct batman_if *if_outgoing);
> -void add_bcast_packet_to_list(struct sk_buff *skb);
> +int  add_bcast_packet_to_list(struct sk_buff *skb);
>  void send_outstanding_bcast_packet(struct work_struct *work);
>  void send_outstanding_bat_packet(struct work_struct *work);
>  void purge_outstanding_packets(void);
> Index: a/batman-adv-kernelland/soft-interface.c
> ===================================================================
> --- a/batman-adv-kernelland/soft-interface.c	(revision 1616)
> +++ a/batman-adv-kernelland/soft-interface.c	(working copy)
> @@ -227,10 +227,10 @@
>  		/* set broadcast sequence number */
>  		bcast_packet->seqno = htons(bcast_seqno);
>  
> -		bcast_seqno++;
> +		/* broadcast packet. on success, increase seqno. */
> +		if (add_bcast_packet_to_list(skb) == NETDEV_TX_OK)
> +			bcast_seqno++;
>  
> -		/* broadcast packet */
> -		add_bcast_packet_to_list(skb);
>  		/* a copy is stored in the bcast list, therefore removing
>  		 * the original skb. */
>  		kfree_skb(skb);
> Index: a/batman-adv-kernelland/main.c
> ===================================================================
> --- a/batman-adv-kernelland/main.c	(revision 1616)
> +++ a/batman-adv-kernelland/main.c	(working copy)
> @@ -46,6 +46,9 @@
>  
>  atomic_t originator_interval;
>  atomic_t vis_interval;
> +atomic_t bcast_queue_left;
> +atomic_t batman_queue_left;
> +
>  int16_t num_hna;
>  int16_t num_ifs;
>  
> @@ -85,6 +88,8 @@
>  	atomic_set(&originator_interval, 1000);
>  	atomic_set(&vis_interval, 1000);/* TODO: raise this later, this is only
>  					 * for debugging now. */
> +	atomic_set(&bcast_queue_left, BCAST_QUEUE_LEN);
> +	atomic_set(&batman_queue_left, BATMAN_QUEUE_LEN);
>  
>  	/* the name should not be longer than 10 chars - see
>  	 * http://lwn.net/Articles/23634/ */
> Index: a/batman-adv-kernelland/aggregation.c
> ===================================================================
> --- a/batman-adv-kernelland/aggregation.c	(revision 1616)
> +++ a/batman-adv-kernelland/aggregation.c	(working copy)
> @@ -95,6 +95,7 @@
>  	return false;
>  }
>  
> +#define atomic_dec_not_zero(v)          atomic_add_unless((v), -1, 0)
>  /* create a new aggregated packet and add this packet to it */
>  static void new_aggregated_packet(unsigned char *packet_buff,
>  			   int packet_len,
> @@ -106,13 +107,26 @@
>  	struct forw_packet *forw_packet_aggr;
>  	unsigned long flags;
>  
> +	/* own packet should always be scheduled */
> +	if (!own_packet) {
> +		if (!atomic_dec_not_zero(&batman_queue_left)) {
> +			bat_dbg(DBG_BATMAN, "batman packet queue full\n");
> +			return;
> +		}
> +	}
> +
>  	forw_packet_aggr = kmalloc(sizeof(struct forw_packet), GFP_ATOMIC);
> -	if (!forw_packet_aggr)
> +	if (!forw_packet_aggr) {
> +		if (!own_packet)
> +			atomic_inc(&batman_queue_left);
>  		return;
> +	}
>  
>  	forw_packet_aggr->packet_buff = kmalloc(MAX_AGGREGATION_BYTES,
>  						GFP_ATOMIC);
>  	if (!forw_packet_aggr->packet_buff) {
> +		if (!own_packet)
> +			atomic_inc(&batman_queue_left);
>  		kfree(forw_packet_aggr);
>  		return;
>  	}
> Index: a/batman-adv-kernelland/main.h
> ===================================================================
> --- a/batman-adv-kernelland/main.h	(revision 1616)
> +++ a/batman-adv-kernelland/main.h	(working copy)
> @@ -70,6 +70,8 @@
>  #define MODULE_ACTIVE 1
>  #define MODULE_DEACTIVATING 2
>  
> +#define BCAST_QUEUE_LEN		256
> +#define BATMAN_QUEUE_LEN 	256
>  
>  /*
>   * Debug Messages
> @@ -133,6 +135,8 @@
>  
>  extern atomic_t originator_interval;
>  extern atomic_t vis_interval;
> +extern atomic_t bcast_queue_left;
> +extern atomic_t batman_queue_left;
>  extern int16_t num_hna;
>  extern int16_t num_ifs;
>  
> 

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 836 bytes --]