swapper: page allocation failure. order:3, mode:0x20

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

After running 2.6.0 on a server for a few days, I met an interesting and annoying problem. I was playing with NFS over gigabit ethernet (e1000) and it was a bit slow. I tried to find out why by running top and I saw syslog-ng eating almost 10% of the 1,3GHz Duron. Looked at the log and there was a huge flood of these messages:

swapper: page allocation failure. order:3, mode:0x20
irssi: page allocation failure. order:3, mode:0x20
swapper: page allocation failure. order:3, mode:0x20
vim: page allocation failure. order:3, mode:0x20
swapper: page allocation failure. order:3, mode:0x20

most of the messages starting with swapper.

After a quick google search it looks like this kind of a problem existed in a bit older 2.5/2.6 serie kernels. It looks like it's still with us.

Linux hamsu.org 2.6.0 #1 Mon Dec 29 21:07:28 EET 2003 i686 AMD Duron(tm) processor AuthenticAMD GNU/Linux

Shortly about the hardware of the machine in case it would matter:
AMD Duron 1,3GHz CPU, 768MB of RAM, Intel PRO/1000MT Desktop and Realtek 8139C NICs.

Pre-empt was disabled in the kernel config and the kernel didn't have any extra patches. A pure vanilla kernel.

I'm not a subscriber so please CC me a copy of messages related to the subject. I'm not sure if I can help much looking at the insides of the kernel, but I will try my best answering any questions about this.
- --
Joonas OH8GDV (ham call sign) OpenPGP: 0x5F72BE43
( 0B37 05E0 0FB4 EB2E 161C DCE6 7F7B C645 5F72 BE43 )
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (GNU/Linux)

iD8DBQE/8+lzf3vGRV9yvkMRAgkIAJ4tjyWtfeDmXCaM0s6w9+ofYLKktACgt+I5 MhYxd+KeJS8QFOjPbtOmykk=
=75d0
-----END PGP SIGNATURE-----

Hi,

Its sounds like you are using either a large MTU (9k?) or TSO. TSO causes the networking stack to think it has a massive MTU and the e1000 card busts it up into proper MTU sized packets. The problem is that it places much more stress on the allocator by asking for these large chunks of memory in interrupt context.

Now e1000 uses TSO (and can regularly ask for 32kB+ kmallocs in interrupt context) perhaps we should look moving the rx buffer refill code into a context that can sleep. Then again its not like we can tolerate much latency in this code path, your rx ring will run out quite quickly :)

BTW We have found increasing /proc/sys/vm/min_free_kbytes can help the situation a bit. Bumping the slab limits for the larger kmallocs (via echo X Y Z > /proc/slab) might be useful too.

We should probably rate limit that printk. Andrew: I was thinking of stealing net_ratelimit and calling it core_ratelimit or whatever. Then wrap these non critical things with it. Overkill?

Anton

Actually my intent was just to remove it (and __GFP_NOWARN) - it's just development-time debug. But it is handy on occasion.

So sure, ratelimit it, make it KERN_INFO and maybe add a dump_stack()?

(printk_ratelimit() may be a suitable name)

Sounds good, I always end up adding a dump_stack there when debugging these problems anyway.

How does this look?

Anton

===== Documentation/sysctl/kernel.txt 1.7 vs edited =====

@@ -251,6 +251,25 @@
 
 ==============================================================
 
+printk_ratelimit:
+
+Some warning messages are rate limited. printk_ratelimit specifies
+the minimum length of time between these messages, by default we
+allow one every 5 seconds.
+
+A value of 0 will disable rate limiting.
+
+==============================================================
+
+printk_ratelimit_burst:
+
+While long term we enforce one message per printk_ratelimit 
+seconds, we do allow a burst of messages to pass through.
+printk_ratelimit_burst specifies the number of messages we can
+send before ratelimiting kicks in.
+
+==============================================================
+
 reboot-cmd: (Sparc only)
 
 ??? This seems to be a way to give an argument to the Sparc

===== include/linux/kernel.h 1.43 vs edited =====

@@ -89,6 +89,8 @@
 
 unsigned long int_sqrt(unsigned long);
 
+extern int printk_ratelimit(void);
+
 static inline void console_silent(void)
 {
 	console_loglevel = 0;

===== include/linux/sysctl.h 1.54 vs edited =====

@@ -127,6 +127,8 @@
 	KERN_PANIC_ON_OOPS=57,  /* int: whether we will panic on an oops */
 	KERN_HPPA_PWRSW=58,	/* int: hppa soft-power enable */
 	KERN_HPPA_UNALIGNED=59,	/* int: hppa unaligned-trap enable */
+	KERN_PRINTK_RATELIMIT=60, /* int: tune printk ratelimiting */
+	KERN_PRINTK_RATELIMIT_BURST=61,	/* int: tune printk ratelimiting */
 };
 
 

===== kernel/printk.c 1.29 vs edited =====

===== kernel/sysctl.c 1.55 vs edited =====

@@ -60,6 +60,8 @@
 extern int pid_max;
 extern int sysctl_lower_zone_protection;
 extern int min_free_kbytes;
+extern int printk_ratelimit_jiffies;
+extern int printk_ratelimit_burst;
 
 /* this is needed for the proc_dointvec_minmax for [fs_]overflow UID and GID */
 static int maxolduid = 65535;

@@ -575,6 +577,22 @@
 		.ctl_name	= KERN_PANIC_ON_OOPS,
 		.procname	= "panic_on_oops",
 		.data		= &panic_on_oops,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dointvec,
+	},
+	{
+		.ctl_name	= KERN_PRINTK_RATELIMIT,
+		.procname	= "printk_ratelimit",
+		.data		= &printk_ratelimit_jiffies,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dointvec_jiffies,
+	},
+	{
+		.ctl_name	= KERN_PRINTK_RATELIMIT_BURST,
+		.procname	= "printk_ratelimit_burst",
+		.data		= &printk_ratelimit_burst,
 		.maxlen		= sizeof(int),
 		.mode		= 0644,
 		.proc_handler	= &proc_dointvec,

===== mm/page_alloc.c 1.176 vs edited =====

@@ -670,10 +670,11 @@
 	}
 
 nopage:
-	if (!(gfp_mask & __GFP_NOWARN)) {
-		printk("%s: page allocation failure."
+	if (!(gfp_mask & __GFP_NOWARN) && printk_ratelimit()) {
+		printk(KERN_WARNING "%s: page allocation failure."
 			" order:%d, mode:0x%x\n",
 			p->comm, order, gfp_mask);
+		dump_stack();
 	}
 	return NULL;
 got_pg:

Good. I guess we need to make net_ratelimit() use this sometime.

Its 100% copied from the networking code. I would have thought we really want that behaviour, if Im on a serial console I can only tolerate a decent sized backtrace every few seconds. If I allow 10 bursts every 5 seconds then im screwed.

Instead we allow the burst of 10 once but then ratelimit it to one per 5 seconds until we have had a long enough period of silence. The main thing is that over the long term we have an average of one message per 5 seconds.

Anton

Am Do, den 01.01.2004 schrieb Anton Blanchard um 14:01:

printk_ratelimit is only to be used for things which we can afford to lose (eg our VM debugging messages). Don't use it on anything important :)

Anton

Am Do, den 01.01.2004 schrieb Anton Blanchard um 23:45:

Other implementations would probably be overkill, so I'll agree with you. :)

If printk_ratelimit is called too often there is probably something wrong going anyway that is worth fixing.

I hate to argue with myself, but thats crap. TSO only affects the TX path and its buffers are created outside interrupt context. So it must be a large MTU causing the failures, regardless it still makes sense to explore rx skb refill outside of interrupt context idea.

Anton

could be done in 2 steps; eg have a "normal path" that starts refilling from process context if, say, half the skbs are used but an emergency fallback to do it from irq context if for whatever reason the process context didn't get around to it....