From patchwork Sat Apr 10 23:56:08 2010 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: =?utf-8?q?Linus_L=C3=BCssing?= X-Patchwork-Id: 57 Return-Path: Received: from fmmailgate03.web.de (fmmailgate03.web.de [217.72.192.234]) by open-mesh.net (Postfix) with ESMTP id 7CA601542F5 for ; Sun, 11 Apr 2010 01:56:13 +0200 (CEST) Received: from smtp08.web.de (fmsmtp08.dlan.cinetic.de [172.20.5.216]) by fmmailgate03.web.de (Postfix) with ESMTP id 1277714D2AC4B for ; Sun, 11 Apr 2010 01:56:13 +0200 (CEST) Received: from [85.179.237.188] (helo=localhost) by smtp08.web.de with asmtp (TLSv1:AES128-SHA:128) (WEB.DE 4.110 #4) id 1O0kX4-0005gY-00 for b.a.t.m.a.n@lists.open-mesh.org; Sun, 11 Apr 2010 01:56:10 +0200 Date: Sun, 11 Apr 2010 01:56:08 +0200 From: Linus =?utf-8?Q?L=C3=BCssing?= To: The list for a Better Approach To Mobile Ad-hoc Networking Message-ID: <20100410235608.GA12381@Linus-Debian> References: <20100405024603.GA11965@pandem0nium> <201004051321.45958.sven.eckelmann@gmx.de> <20100405144035.GA13768@pandem0nium> <20100405150605.GA15893@pandem0nium> <20100407081123.GA2378@pandem0nium> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20100407081123.GA2378@pandem0nium> User-Agent: Mutt/1.5.20 (2009-06-14) Sender: linus.luessing@web.de X-Sender: linus.luessing@web.de X-Provags-ID: V01U2FsdGVkX19mKtpI/uvMOrD6Wkyr3T7LEUqTSnYXodzCfE9x MmYYrRl3Qj4J2BXyV2c394cW9AswnDTJ2llXjJS7lJcmiOkI+o OvW8VgwS8FxYc0UtM3ww== Subject: Re: [B.A.T.M.A.N.] [PATCHv3] batman-adv: Limit queue lengths for batman and broadcast packets X-BeenThere: b.a.t.m.a.n@lists.open-mesh.org X-Mailman-Version: 2.1.11 Precedence: list Reply-To: The list for a Better Approach To Mobile Ad-hoc Networking List-Id: The list for a Better Approach To Mobile Ad-hoc Networking List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 10 Apr 2010 23:56:13 -0000 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:[] 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] [] ? e1000_clean+0x3c/0x216 [e1000] [ 3508.988304] [] ? net_rx_action+0x9c/0x1b9 [ 3508.988304] [] ? __do_softirq+0x66/0xd3 [ 3508.988304] [] ? do_softirq+0x45/0x53 [ 3508.988304] [] ? local_bh_enable+0x66/0x71 [ 3508.988304] [] ? dev_queue_xmit+0x287/0x2be [ 3508.988304] [] ? send_outstanding_bcast_packet+0x0/0xa5 [batman_adv] [ 3508.988304] [] ? send_outstanding_bcast_packet+0x5f/0xa5 [batman_adv] [ 3508.988304] [] ? run_workqueue+0x74/0xf2 [ 3508.988304] [] ? worker_thread+0x0/0xbd [ 3508.988304] [] ? worker_thread+0xb3/0xbd [ 3508.988304] [] ? autoremove_wake_function+0x0/0x2d [ 3508.988304] [] ? kthread+0x38/0x5d [ 3508.988304] [] ? kthread+0x0/0x5d [ 3508.988304] [] ? 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: -------------------------------------------------------------- -------------------------------------------------------------- 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 > --- > 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; > > --- 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();