Re: [B.A.T.M.A.N.] slowpath warning

[Simon Wunderlich <simon.wunderlich@s2003.tu-chemnitz.de>]

[-- Attachment #1.1: Type: text/plain, Size: 4979 bytes --]

Hello,

i can reproduce the slowpath warning in the trunk within my qemu setup. When i
start a server, some of the clients show this slow path warning.

I've tried Andrews patch, and i can not see any memory leaks - it varies in a 
100k window. However some of the servers crash after some time (30 minutes)
without any special trigger i am aware of. Stack trace is this:

root@OpenWrt:/# ------------[ cut here ]------------
WARNING: at lib/kref.c:43 kref_get+0x18/0x30()
Hardware name:
Modules linked in: via_velocity via_rhine tg3 sis900 r8169 pcnet32 ne2k_pci 8390 e1000 e100 batman_adv 8139too 3c59x nf_nat_tftp nf_conntrack_tftp nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack pppoe pppox libphy ipt_REJECT xt_TCPMSS ipt_LOG xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables ppp_async ppp_generic slhc natsemi crc_ccitt ipv6
Pid: 570, comm: bat_events Not tainted 2.6.31.1 #32
Call Trace:
 [<c10dd608>] ? kref_get+0x18/0x30
 [<c101f55f>] ? warn_slowpath_common+0x7f/0xb0
 [<c10dd608>] ? kref_get+0x18/0x30
 [<c101f5a3>] ? warn_slowpath_null+0x13/0x20
 [<c10dd608>] ? kref_get+0x18/0x30
 [<c2ac51a2>] ? proc_vis_read_prim_sec+0x352/0x5a0 [batman_adv]
 [<c2ac4ee0>] ? proc_vis_read_prim_sec+0x90/0x5a0 [batman_adv]
 [<c102d23a>] ? worker_thread+0xca/0x150
 [<c102fd80>] ? autoremove_wake_function+0x0/0x50
 [<c102d170>] ? worker_thread+0x0/0x150
 [<c102fbc3>] ? kthread+0x73/0x90
 [<c102fb50>] ? kthread+0x0/0x90
 [<c1003813>] ? kernel_thread_helper+0x7/0x14
---[ end trace 4f770856ce7e0712 ]---
------------[ cut here ]------------
kernel BUG at mm/slub.c:2929!
invalid opcode: 0000 [#1]
last sysfs file: /sys/kernel/uevent_seqnum
Modules linked in: via_velocity via_rhine tg3 sis900 r8169 pcnet32 ne2k_pci 8390 e1000 e100 batman_adv 8139too 3c59x nf_nat_tftp nf_conntrack_tftp nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_conntrack_ftp ipt_MASQUERADE iptable_nat nf_nat xt_NOTRACK iptable_raw xt_state nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack pppoe pppox libphy ipt_REJECT xt_TCPMSS ipt_LOG xt_multiport xt_mac xt_limit iptable_mangle iptable_filter ip_tables xt_tcpudp x_tables ppp_async ppp_generic slhc natsemi crc_ccitt ipv6

Pid: 570, comm: bat_events Tainted: G        W  (2.6.31.1 #32)
EIP: 0060:[<c1064669>] EFLAGS: 00010046 CPU: 0
EIP is at kfree+0x49/0xc0
EAX: 00000000 EBX: c1f5dd94 ECX: 40080000 EDX: c133cba0
ESI: c2ac5540 EDI: c1f5dd80 EBP: 00000216 ESP: c0d06eec
 DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068
Process bat_events (pid: 570, ti=c0d06000 task=c18d0000 task.ti=c0d06000)
Stack:
 00000002 c1f5dd94 c1f5dd94 c2ac5540 c1f5dda4 c10dd5cf c1f5dda4 00000000
<0> c2ac538b c0d06f68 c0e0504a c1f5dd84 c1f5dd94 c1f5dd80 c1f5dd80 000022a0
<0> 00000046 c0e05024 c0e05030 00000286 00000086 c1f5dda4 0000003f 00000080
Call Trace:
 [<c2ac5540>] ? vis_init+0x150/0x1b0 [batman_adv]
 [<c10dd5cf>] ? kref_put+0x4f/0x70
 [<c2ac538b>] ? proc_vis_read_prim_sec+0x53b/0x5a0 [batman_adv]
 [<c2ac4ee0>] ? proc_vis_read_prim_sec+0x90/0x5a0 [batman_adv]
 [<c102d23a>] ? worker_thread+0xca/0x150
 [<c102fd80>] ? autoremove_wake_function+0x0/0x50
 [<c102d170>] ? worker_thread+0x0/0x150
 [<c102fbc3>] ? kthread+0x73/0x90
 [<c102fb50>] ? kthread+0x0/0x90
 [<c1003813>] ? kernel_thread_helper+0x7/0x14
Code: 00 40 a1 80 cb 2e c1 c1 ea 0c c1 e2 05 01 c2 8b 0a 89 c8 25 00 80 00 00 66 85 c0 74 05 8b 52 0c 8b 0a 84 c9 78 24 f6 c5 c0 75 09 <0f> 0b 90 8d 74 26 00 eb fe 8b 5c 24 08 89 d0 8b 74 24 0c 8b 7c
EIP: [<c1064669>] kfree+0x49/0xc0 SS:ESP 0068:c0d06eec
---[ end trace 4f770856ce7e0713 ]---

Please note that in this moment, i have not queried the vis_data file, so 
the proc_vis_read_prim_sec call is probably not correctly reported. Furthermore
there are some more stack traces in vfs/mount and then the boxes reboot -
we probably write at some bad memory position.

I've changed Andrews patch a little bit, and could not crash my 9 kvm instances
when running it some hours last night. I've added kref_get() calls when the info 
packets get referenced from the send_list, this reference is removed with 
kref_put() in the send_vis_packets() after sending the packet. The disadvantage 
of this solution is that in a race condition, we might (unnecessarily) send out an 
old packet. No memory leaks as far as i could see after running some hours.

Please give it a try (patch is attached to this e-mail)!

best regards,
	Simon



On Thu, Feb 11, 2010 at 11:01:56AM +0100, Andrew Lunn wrote:
> On Thu, Feb 11, 2010 at 10:46:59AM +0100, Andrew Lunn wrote:
> > Hi Linus
> > 
> > Here is a new version of the patch. I've tested it this time using
> > five UML machines. It should not immediately opps now. 
> 
> Instead is will leak memory and crash after a while...
> 
> I will try to find the memory leak.
> 
>   Andrew
> 

[-- Attachment #1.2: vis_refcount.patch --]
[-- Type: text/x-diff, Size: 13632 bytes --]

taging: batman-adv: Don't have interrupts disabled while sending.

send_vis_packets() would disable interrupts before calling
dev_queue_xmit() which resulting in a backtrace in local_bh_enable().
Fix this by using kref on the vis_info object so that we can call
send_vis_packets() without holding vis_hash_lock. vis_hash_lock also
used to protect recv_list, so we now need a new lock to protect that
instead of vis_hash_lock.

Also a few checkpatch cleanups.

Reported-by: Linus Luessing <linus.luessing@web.de>
Signed-off-by: Andrew Lunn <andrew@lunn.ch>
Signed-off-by: Simon Wunderlich <siwu@hrz.tu-chemnitz.de>
===================================================================
--- batman-adv-kernelland/vis.c	(revision 1578)
+++ batman-adv-kernelland/vis.c	(working copy)
@@ -30,22 +30,26 @@
 
 struct hashtable_t *vis_hash;
 DEFINE_SPINLOCK(vis_hash_lock);
+static DEFINE_SPINLOCK(recv_list_lock);
 static struct vis_info *my_vis_info;
 static struct list_head send_list;	/* always locked with vis_hash_lock */
 
 static void start_vis_timer(void);
 
 /* free the info */
-static void free_info(void *data)
+static void free_info(struct kref *ref)
 {
-	struct vis_info *info = data;
+	struct vis_info *info = container_of(ref, struct vis_info, refcount);
 	struct recvlist_node *entry, *tmp;
+	unsigned long flags;
 
 	list_del_init(&info->send_list);
+	spin_lock_irqsave(&recv_list_lock, flags);
 	list_for_each_entry_safe(entry, tmp, &info->recv_list, list) {
 		list_del(&entry->list);
 		kfree(entry);
 	}
+	spin_unlock_irqrestore(&recv_list_lock, flags);
 	kfree(info);
 }
 
@@ -147,32 +151,41 @@
 static void recv_list_add(struct list_head *recv_list, char *mac)
 {
 	struct recvlist_node *entry;
+	unsigned long flags;
+
 	entry = kmalloc(sizeof(struct recvlist_node), GFP_ATOMIC);
 	if (!entry)
 		return;
 
 	memcpy(entry->mac, mac, ETH_ALEN);
+	spin_lock_irqsave(&recv_list_lock, flags);
 	list_add_tail(&entry->list, recv_list);
+	spin_unlock_irqrestore(&recv_list_lock, flags);
 }
 
 /* returns 1 if this mac is in the recv_list */
 static int recv_list_is_in(struct list_head *recv_list, char *mac)
 {
 	struct recvlist_node *entry;
+	unsigned long flags;
 
+	spin_lock_irqsave(&recv_list_lock, flags);
 	list_for_each_entry(entry, recv_list, list) {
-		if (memcmp(entry->mac, mac, ETH_ALEN) == 0)
+		if (memcmp(entry->mac, mac, ETH_ALEN) == 0) {
+			spin_unlock_irqrestore(&recv_list_lock, flags);
 			return 1;
+		}
 	}
-
+	spin_unlock_irqrestore(&recv_list_lock, flags);
 	return 0;
 }
 
 /* try to add the packet to the vis_hash. return NULL if invalid (e.g. too old,
- * broken.. ).  vis hash must be locked outside.  is_new is set when the packet
+ * broken.. ).	vis hash must be locked outside.  is_new is set when the packet
  * is newer than old entries in the hash. */
 static struct vis_info *add_packet(struct vis_packet *vis_packet,
-				   int vis_info_len, int *is_new)
+				   int vis_info_len, int *is_new,
+				   int make_broadcast)
 {
 	struct vis_info *info, *old_info;
 	struct vis_info search_elem;
@@ -199,13 +212,14 @@
 		}
 		/* remove old entry */
 		hash_remove(vis_hash, old_info);
-		free_info(old_info);
+		kref_put(&old_info->refcount, free_info);
 	}
 
 	info = kmalloc(sizeof(struct vis_info) + vis_info_len, GFP_ATOMIC);
 	if (info == NULL)
 		return NULL;
 
+	kref_init(&info->refcount);
 	INIT_LIST_HEAD(&info->send_list);
 	INIT_LIST_HEAD(&info->recv_list);
 	info->first_seen = jiffies;
@@ -215,16 +229,21 @@
 	/* initialize and add new packet. */
 	*is_new = 1;
 
+	/* Make it a broadcast packet, if required */
+	if (make_broadcast)
+		memcpy(info->packet.target_orig, broadcastAddr, ETH_ALEN);
+
 	/* repair if entries is longer than packet. */
 	if (info->packet.entries * sizeof(struct vis_info_entry) > vis_info_len)
-		info->packet.entries = vis_info_len / sizeof(struct vis_info_entry);
+		info->packet.entries = vis_info_len /
+			sizeof(struct vis_info_entry);
 
 	recv_list_add(&info->recv_list, info->packet.sender_orig);
 
 	/* try to add it */
 	if (hash_add(vis_hash, info) < 0) {
 		/* did not work (for some reason) */
-		free_info(info);
+		kref_put(&old_info->refcount, free_info);
 		info = NULL;
 	}
 
@@ -235,21 +254,24 @@
 void receive_server_sync_packet(struct vis_packet *vis_packet, int vis_info_len)
 {
 	struct vis_info *info;
-	int is_new;
+	int is_new, make_broadcast;
 	unsigned long flags;
 	int vis_server = atomic_read(&vis_mode);
 
+	make_broadcast = (vis_server == VIS_TYPE_SERVER_SYNC);
+
 	spin_lock_irqsave(&vis_hash_lock, flags);
-	info = add_packet(vis_packet, vis_info_len, &is_new);
+	info = add_packet(vis_packet, vis_info_len, &is_new, make_broadcast);
 	if (info == NULL)
 		goto end;
 
 	/* only if we are server ourselves and packet is newer than the one in
 	 * hash.*/
 	if (vis_server == VIS_TYPE_SERVER_SYNC && is_new) {
-		memcpy(info->packet.target_orig, broadcastAddr, ETH_ALEN);
-		if (list_empty(&info->send_list))
+		if (list_empty(&info->send_list)) {
+			kref_get(&info->refcount);
 			list_add_tail(&info->send_list, &send_list);
+		}
 	}
 end:
 	spin_unlock_irqrestore(&vis_hash_lock, flags);
@@ -263,31 +285,38 @@
 	int is_new;
 	unsigned long flags;
 	int vis_server = atomic_read(&vis_mode);
+	int are_target = 0;
 
 	/* clients shall not broadcast. */
 	if (is_bcast(vis_packet->target_orig))
 		return;
 
+	/* Are we the target for this VIS packet? */
+	if (vis_server == VIS_TYPE_SERVER_SYNC	&&
+	    is_my_mac(vis_packet->target_orig))
+		are_target = 1;
+
 	spin_lock_irqsave(&vis_hash_lock, flags);
-	info = add_packet(vis_packet, vis_info_len, &is_new);
+	info = add_packet(vis_packet, vis_info_len, &is_new, are_target);
 	if (info == NULL)
 		goto end;
 	/* note that outdated packets will be dropped at this point. */
 
 
 	/* send only if we're the target server or ... */
-	if (vis_server == VIS_TYPE_SERVER_SYNC  &&
-	    is_my_mac(info->packet.target_orig) &&
-	    is_new) {
+	if (are_target && is_new) {
 		info->packet.vis_type = VIS_TYPE_SERVER_SYNC;	/* upgrade! */
-		memcpy(info->packet.target_orig, broadcastAddr, ETH_ALEN);
-		if (list_empty(&info->send_list))
+		if (list_empty(&info->send_list)) {
+			kref_get(&info->refcount);
 			list_add_tail(&info->send_list, &send_list);
+		}
 
 		/* ... we're not the recipient (and thus need to forward). */
 	} else if (!is_my_mac(info->packet.target_orig)) {
-		if (list_empty(&info->send_list))
+		if (list_empty(&info->send_list)) {
+			kref_get(&info->refcount);
 			list_add_tail(&info->send_list, &send_list);
+		}
 	}
 end:
 	spin_unlock_irqrestore(&vis_hash_lock, flags);
@@ -362,14 +391,17 @@
 	while (hash_iterate(orig_hash, &hashit_global)) {
 		orig_node = hashit_global.bucket->data;
 		if (orig_node->router != NULL
-			&& compare_orig(orig_node->router->addr, orig_node->orig)
+			&& compare_orig(orig_node->router->addr,
+					orig_node->orig)
 			&& orig_node->batman_if
 			&& (orig_node->batman_if->if_active == IF_ACTIVE)
 		    && orig_node->router->tq_avg > 0) {
 
 			/* fill one entry into buffer. */
 			entry = &entry_array[info->packet.entries];
-			memcpy(entry->src, orig_node->batman_if->net_dev->dev_addr, ETH_ALEN);
+			memcpy(entry->src,
+			       orig_node->batman_if->net_dev->dev_addr,
+			       ETH_ALEN);
 			memcpy(entry->dest, orig_node->orig, ETH_ALEN);
 			entry->quality = orig_node->router->tq_avg;
 			info->packet.entries++;
@@ -401,6 +433,8 @@
 	return 0;
 }
 
+/* free old vis packets. Must be called with this vis_hash_lock
+ * held */
 static void purge_vis_packets(void)
 {
 	HASHIT(hashit);
@@ -413,7 +447,7 @@
 		if (time_after(jiffies,
 			       info->first_seen + (VIS_TIMEOUT*HZ)/1000)) {
 			hash_remove_bucket(vis_hash, &hashit);
-			free_info(info);
+			kref_put(&info->refcount, free_info);
 		}
 	}
 }
@@ -423,6 +457,8 @@
 	HASHIT(hashit);
 	struct orig_node *orig_node;
 	unsigned long flags;
+	struct batman_if *batman_if;
+	uint8_t dstaddr[ETH_ALEN];
 
 	spin_lock_irqsave(&orig_hash_lock, flags);
 
@@ -431,46 +467,57 @@
 		orig_node = hashit.bucket->data;
 
 		/* if it's a vis server and reachable, send it. */
-		if (orig_node &&
-		    (orig_node->flags & VIS_SERVER) &&
-		    orig_node->batman_if &&
-		    orig_node->router) {
+		if ((!orig_node) || (!orig_node->batman_if) ||
+		    (!orig_node->router))
+			continue;
+		if (!(orig_node->flags & VIS_SERVER))
+			continue;
+		/* don't send it if we already received the packet from
+		 * this node. */
+		if (recv_list_is_in(&info->recv_list, orig_node->orig))
+			continue;
 
-			/* don't send it if we already received the packet from
-			 * this node. */
-			if (recv_list_is_in(&info->recv_list, orig_node->orig))
-				continue;
+		memcpy(info->packet.target_orig, orig_node->orig, ETH_ALEN);
+		batman_if = orig_node->batman_if;
+		memcpy(dstaddr, orig_node->router->addr, ETH_ALEN);
+		spin_unlock_irqrestore(&orig_hash_lock, flags);
 
-			memcpy(info->packet.target_orig,
-			       orig_node->orig, ETH_ALEN);
+		send_raw_packet((unsigned char *)&info->packet,
+				packet_length, batman_if, dstaddr);
 
-			send_raw_packet((unsigned char *) &info->packet,
-					packet_length,
-					orig_node->batman_if,
-					orig_node->router->addr);
-		}
+		spin_lock_irqsave(&orig_hash_lock, flags);
+
 	}
+	spin_unlock_irqrestore(&orig_hash_lock, flags);
 	memcpy(info->packet.target_orig, broadcastAddr, ETH_ALEN);
-	spin_unlock_irqrestore(&orig_hash_lock, flags);
 }
 
 static void unicast_vis_packet(struct vis_info *info, int packet_length)
 {
 	struct orig_node *orig_node;
 	unsigned long flags;
+	struct batman_if *batman_if;
+	uint8_t dstaddr[ETH_ALEN];
 
 	spin_lock_irqsave(&orig_hash_lock, flags);
 	orig_node = ((struct orig_node *)
 		     hash_find(orig_hash, info->packet.target_orig));
 
-	if ((orig_node != NULL) &&
-	    (orig_node->batman_if != NULL) &&
-	    (orig_node->router != NULL)) {
-		send_raw_packet((unsigned char *) &info->packet, packet_length,
-				orig_node->batman_if,
-				orig_node->router->addr);
-	}
+	if ((!orig_node) || (!orig_node->batman_if) || (!orig_node->router))
+		goto out;
+
+	/* don't lock while sending the packets ... we therefore
+	 * copy the required data before sending */
+	batman_if = orig_node->batman_if;
+	memcpy(dstaddr, orig_node->router->addr, ETH_ALEN);
 	spin_unlock_irqrestore(&orig_hash_lock, flags);
+
+	send_raw_packet((unsigned char *)&info->packet,
+			packet_length, batman_if, dstaddr);
+	return;
+
+out:
+	spin_unlock_irqrestore(&orig_hash_lock, flags);
 }
 
 /* only send one vis packet. called from send_vis_packets() */
@@ -503,15 +550,23 @@
 	unsigned long flags;
 
 	spin_lock_irqsave(&vis_hash_lock, flags);
+
 	purge_vis_packets();
 
-	if (generate_vis_packet() == 0)
+	if (generate_vis_packet() == 0) {
 		/* schedule if generation was successful */
+		kref_get(&my_vis_info->refcount);
 		list_add_tail(&my_vis_info->send_list, &send_list);
+	}
 
 	list_for_each_entry_safe(info, temp, &send_list, send_list) {
+		spin_unlock_irqrestore(&vis_hash_lock, flags);
+
+		send_vis_packet(info);
+
+		spin_lock_irqsave(&vis_hash_lock, flags);
 		list_del_init(&info->send_list);
-		send_vis_packet(info);
+		kref_put(&info->refcount, free_info);
 	}
 	spin_unlock_irqrestore(&vis_hash_lock, flags);
 	start_vis_timer();
@@ -544,6 +599,7 @@
 	my_vis_info->first_seen = jiffies - atomic_read(&vis_interval);
 	INIT_LIST_HEAD(&my_vis_info->recv_list);
 	INIT_LIST_HEAD(&my_vis_info->send_list);
+	kref_init(&my_vis_info->refcount);
 	my_vis_info->packet.version = COMPAT_VERSION;
 	my_vis_info->packet.packet_type = BAT_VIS;
 	my_vis_info->packet.ttl = TTL;
@@ -557,9 +613,9 @@
 
 	if (hash_add(vis_hash, my_vis_info) < 0) {
 		printk(KERN_ERR
-			  "batman-adv:Can't add own vis packet into hash\n");
-		free_info(my_vis_info);	/* not in hash, need to remove it
-					 * manually. */
+		       "batman-adv:Can't add own vis packet into hash\n");
+		/* not in hash, need to remove it manually. */
+		kref_put(&my_vis_info->refcount, free_info);
 		goto err;
 	}
 
@@ -573,6 +629,13 @@
 	return 0;
 }
 
+/* Decrease the reference count on a hash item info */
+static void free_info_ref(void *data)
+{
+	struct vis_info *info = data;
+	kref_put(&info->refcount, free_info);
+}
+
 /* shutdown vis-server */
 void vis_quit(void)
 {
@@ -584,7 +647,7 @@
 
 	spin_lock_irqsave(&vis_hash_lock, flags);
 	/* properly remove, kill timers ... */
-	hash_delete(vis_hash, free_info);
+	hash_delete(vis_hash, free_info_ref);
 	vis_hash = NULL;
 	my_vis_info = NULL;
 	spin_unlock_irqrestore(&vis_hash_lock, flags);
@@ -594,5 +657,5 @@
 static void start_vis_timer(void)
 {
 	queue_delayed_work(bat_event_workqueue, &vis_timer_wq,
-			   (atomic_read(&vis_interval) * HZ ) / 1000);
+			   (atomic_read(&vis_interval) * HZ) / 1000);
 }
Index: batman-adv-kernelland/vis.h
===================================================================
--- batman-adv-kernelland/vis.h	(revision 1578)
+++ batman-adv-kernelland/vis.h	(working copy)
@@ -29,6 +29,7 @@
 			    /* list of server-neighbors we received a vis-packet
 			     * from.  we should not reply to them. */
 	struct list_head send_list;
+	struct kref refcount;
 	/* this packet might be part of the vis send queue. */
 	struct vis_packet packet;
 	/* vis_info may follow here*/

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