(cc IPW maintainers and mailing lists)
On Wed, 26 Aug 2009 10:37:49 +0100 Mel Gorman <[email protected]> wrote:
> On Wed, Aug 26, 2009 at 10:27:41AM +0200, Johannes Weiner wrote:
> > [Cc netdev]
> >
> > On Wed, Aug 26, 2009 at 09:09:44AM +0300, Pekka Enberg wrote:
> > > On Tue, Aug 25, 2009 at 11:34 PM, Rafael J. Wysocki<[email protected]> wrote:
> > > > This message has been generated automatically as a part of a report
> > > > of recent regressions.
> > > >
> > > > The following bug entry is on the current list of known regressions
> > > > from 2.6.30. __Please verify if it still should be listed and let me know
> > > > (either way).
> > > >
> > > > Bug-Entry __ __ __ : http://bugzilla.kernel.org/show_bug.cgi?id=14016
> > > > Subject __ __ __ __ : mm/ipw2200 regression
> > > > Submitter __ __ __ : Bartlomiej Zolnierkiewicz <[email protected]>
> > > > Date __ __ __ __ __ __: 2009-08-15 16:56 (11 days old)
> > > > References __ __ __: http://marc.info/?l=linux-kernel&m=125036437221408&w=4
> > >
> > > If am reading the page allocator dump correctly, there's plenty of
> > > pages left but we're unable to satisfy an order 6 allocation. There's
> > > no slab allocator involved so the page allocator changes that went
> > > into 2.6.31 seem likely. Mel, ideas?
> >
> > It's an atomic order-6 allocation, the chances for this to succeed
> > after some uptime become infinitesimal. The chunks > order-2 are
> > pretty much exhausted on this dump.
> >
> > 64 pages, presumably 256k, for fw->boot_size while current ipw
> > firmware images have ~188k. I don't know jack squat about this
> > driver, but given the field name and the struct:
> >
> > struct ipw_fw {
> > __le32 ver;
> > __le32 boot_size;
> > __le32 ucode_size;
> > __le32 fw_size;
> > u8 data[0];
> > };
> >
> > fw->boot_size alone being that big sounds a bit fishy to me.
> >
>
> Agreed. While there are a low number of order-6 pages free in the page
> allocation failure dump, there are not enough for watermarks to be
> satisified. As it's atomic, there is little that can be done from a VM
> perspective and it's the responsibility of the driver. I'm no driver expert
> but I'll have a go at fixing it anyway.
>
> My reading of this is that the firmware is being loaded from a workqueue and
> I am failing to see any restriction on sleeping in the path. It would appear
> that the driver just used the most convenient *_alloc_coherent function
> available forgetting that it assumes GFP_ATOMIC. Can someone who does know
> which way is up with a driver tell me why the patch below might not
> work?
>
> Bartlomiej, any chance you could give this a spin? Preferably, you'd
> have preempt enabled and CONFIG_DEBUG_SPINLOCK_SLEEP on as well because
> that combination will complain loudly if we really can't sleep in this
> path.
>
> =====
> ipw2200: Avoid large GFP_ATOMIC allocation during firmware loading
>
> ipw2200 uses pci_alloc_consistent() to allocate a large coherent buffer for
> the loading of firmware which is an order-6 allocation of GFP_ATOMIC. At
> system start-up time, this is not a problem. However, the firmware on the
> card can get confused and the corrective action taken is to reload the
> firmware and reinit the card. High-order GFP_ATOMIC allocations of this
> type can and will fail when the system is already up and running.
>
> As the firmware is loaded from a workqueue, it should be possible for
> the driver to go to sleep. This patch converts the call of
> pci_alloc_consistent() which assumes GFP_ATOMIC to dma_alloc_coherent()
> which can specify its own flags.
>
> The big downside with this patch is that it uses GFP_REPEAT to avoid the
> driver unloading. There is potential that this will cause a reclaim
> storm as the machine tries to find a free order-6 buffer. A suggested
> alternative for the driver owner is in the comments.
>
> Signed-off-by: Mel Gorman <[email protected]>
> ---
> drivers/net/wireless/ipw2x00/ipw2200.c | 14 +++++++++++++-
> 1 file changed, 13 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/net/wireless/ipw2x00/ipw2200.c b/drivers/net/wireless/ipw2x00/ipw2200.c
> index 44c29b3..f2e251e 100644
> --- a/drivers/net/wireless/ipw2x00/ipw2200.c
> +++ b/drivers/net/wireless/ipw2x00/ipw2200.c
> @@ -3167,7 +3167,19 @@ static int ipw_load_firmware(struct ipw_priv *priv, u8 * data, size_t len)
> u8 *shared_virt;
>
> IPW_DEBUG_TRACE("<< : \n");
> - shared_virt = pci_alloc_consistent(priv->pci_dev, len, &shared_phys);
> +
> + /*
> + * This is a whopping large allocation, in or around order-6 so
> + * dma_alloc_coherent is used to specify the GFP_KERNEL|__GFP_REPEAT
> + * flags. Note that this action means the system could go into a
> + * reclaim loop until it cannot reclaim any more trying to satisfy
> + * the allocation. It would be preferable if one buffer is allocated
> + * at driver initialisation and reused when the firmware needs to
> + * be reloaded, overwriting the existing firmware each time
> + */
> + shared_virt = dma_alloc_coherent(
> + priv->pci_dev == NULL ? NULL : &priv->pci_dev->dev,
> + len, &shared_phys, GFP_KERNEL|__GFP_REPEAT);
>
> if (!shared_virt)
> return -ENOMEM;
Of course, the risk of making a change like this is that we'll then go
and leave it there.
To fix this code properly we should, as you say, stop doing an order-6
allocation altogether.
And right now I think it's doing _two_ order-6 allocations:
shared_virt = pci_alloc_consistent(priv->pci_dev, len, &shared_phys);
if (!shared_virt)
return -ENOMEM;
memmove(shared_virt, data, len);
whoever allocated `data' is being obnoxious as well.
It is perhaps pretty simple to make the second (GFP_ATOMIC) allocation
go away. The code is already conveniently structured to do this:
do {
chunk = (struct fw_chunk *)(data + offset);
offset += sizeof(struct fw_chunk);
/* build DMA packet and queue up for sending */
/* dma to chunk->address, the chunk->length bytes from data +
* offeset*/
/* Dma loading */
rc = ipw_fw_dma_add_buffer(priv, shared_phys + offset,
le32_to_cpu(chunk->address),
le32_to_cpu(chunk->length));
if (rc) {
IPW_DEBUG_INFO("dmaAddBuffer Failed\n");
goto out;
}
offset += le32_to_cpu(chunk->length);
} while (offset < len);
what is the typical/expected value of chunk->length here? If it's
significantly less than 4096*(2^6), could we convert this function to
use a separate DMAable allocation per fw_chunk?
On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
s/2.6.30/2.6.31-rc6/
The issue has always been there but it was some recent change that
explicitly triggered the allocation failures (after 2.6.31-rc1).
> likely to fail and should always be avoided.
>
> The patch fixes this problem by replacing the original order-6
> pci_alloc_consistent() with an array of order-1 pages from a pci pool.
> This utilized the ipw2200 DMA command blocks (up to 64 slots). The
> maximum firmware size support remains the same (64*8K).
>
> This patch fixes bug http://bugzilla.kernel.org/show_bug.cgi?id=14016
>
> Cc: Andrew Morton <[email protected]>
> Cc: Mel Gorman <[email protected]>
> Signed-off-by: Zhu Yi <[email protected]>
Thanks for the fix (also kudos to other people helping with the bugreport),
it works fine so far and looks OK to me:
Tested-and-reviewed-by: Bartlomiej Zolnierkiewicz <[email protected]>
Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
likely to fail and should always be avoided.
The patch fixes this problem by replacing the original order-6
pci_alloc_consistent() with an array of order-1 pages from a pci pool.
This utilized the ipw2200 DMA command blocks (up to 64 slots). The
maximum firmware size support remains the same (64*8K).
This patch fixes bug http://bugzilla.kernel.org/show_bug.cgi?id=14016
Cc: Andrew Morton <[email protected]>
Cc: Mel Gorman <[email protected]>
Signed-off-by: Zhu Yi <[email protected]>
---
drivers/net/wireless/ipw2x00/ipw2200.c | 120 ++++++++++++++++++--------------
1 files changed, 67 insertions(+), 53 deletions(-)
diff --git a/drivers/net/wireless/ipw2x00/ipw2200.c b/drivers/net/wireless/ipw2x00/ipw2200.c
index 6dcac73..f593fbb 100644
--- a/drivers/net/wireless/ipw2x00/ipw2200.c
+++ b/drivers/net/wireless/ipw2x00/ipw2200.c
@@ -2874,45 +2874,27 @@ static int ipw_fw_dma_add_command_block(struct ipw_priv *priv,
return 0;
}
-static int ipw_fw_dma_add_buffer(struct ipw_priv *priv,
- u32 src_phys, u32 dest_address, u32 length)
+static int ipw_fw_dma_add_buffer(struct ipw_priv *priv, dma_addr_t *src_address,
+ int nr, u32 dest_address, u32 len)
{
- u32 bytes_left = length;
- u32 src_offset = 0;
- u32 dest_offset = 0;
- int status = 0;
+ int ret, i;
+ u32 size;
+
IPW_DEBUG_FW(">> \n");
- IPW_DEBUG_FW_INFO("src_phys=0x%x dest_address=0x%x length=0x%x\n",
- src_phys, dest_address, length);
- while (bytes_left > CB_MAX_LENGTH) {
- status = ipw_fw_dma_add_command_block(priv,
- src_phys + src_offset,
- dest_address +
- dest_offset,
- CB_MAX_LENGTH, 0, 0);
- if (status) {
+ IPW_DEBUG_FW_INFO("nr=%d dest_address=0x%x len=0x%x\n",
+ nr, dest_address, len);
+
+ for (i = 0; i < nr; i++) {
+ size = min_t(u32, len - i * CB_MAX_LENGTH, CB_MAX_LENGTH);
+ ret = ipw_fw_dma_add_command_block(priv, src_address[i],
+ dest_address +
+ i * CB_MAX_LENGTH, size,
+ 0, 0);
+ if (ret) {
IPW_DEBUG_FW_INFO(": Failed\n");
return -1;
} else
IPW_DEBUG_FW_INFO(": Added new cb\n");
-
- src_offset += CB_MAX_LENGTH;
- dest_offset += CB_MAX_LENGTH;
- bytes_left -= CB_MAX_LENGTH;
- }
-
- /* add the buffer tail */
- if (bytes_left > 0) {
- status =
- ipw_fw_dma_add_command_block(priv, src_phys + src_offset,
- dest_address + dest_offset,
- bytes_left, 0, 0);
- if (status) {
- IPW_DEBUG_FW_INFO(": Failed on the buffer tail\n");
- return -1;
- } else
- IPW_DEBUG_FW_INFO
- (": Adding new cb - the buffer tail\n");
}
IPW_DEBUG_FW("<< \n");
@@ -3160,59 +3142,91 @@ static int ipw_load_ucode(struct ipw_priv *priv, u8 * data, size_t len)
static int ipw_load_firmware(struct ipw_priv *priv, u8 * data, size_t len)
{
- int rc = -1;
+ int ret = -1;
int offset = 0;
struct fw_chunk *chunk;
- dma_addr_t shared_phys;
- u8 *shared_virt;
+ int total_nr = 0;
+ int i;
+ struct pci_pool *pool;
+ u32 *virts[CB_NUMBER_OF_ELEMENTS_SMALL];
+ dma_addr_t phys[CB_NUMBER_OF_ELEMENTS_SMALL];
IPW_DEBUG_TRACE("<< : \n");
- shared_virt = pci_alloc_consistent(priv->pci_dev, len, &shared_phys);
- if (!shared_virt)
+ pool = pci_pool_create("ipw2200", priv->pci_dev, CB_MAX_LENGTH, 0, 0);
+ if (!pool) {
+ IPW_ERROR("pci_pool_create failed\n");
return -ENOMEM;
-
- memmove(shared_virt, data, len);
+ }
/* Start the Dma */
- rc = ipw_fw_dma_enable(priv);
+ ret = ipw_fw_dma_enable(priv);
/* the DMA is already ready this would be a bug. */
BUG_ON(priv->sram_desc.last_cb_index > 0);
do {
+ u32 chunk_len;
+ u8 *start;
+ int size;
+ int nr = 0;
+
chunk = (struct fw_chunk *)(data + offset);
offset += sizeof(struct fw_chunk);
+ chunk_len = le32_to_cpu(chunk->length);
+ start = data + offset;
+
+ nr = (chunk_len + CB_MAX_LENGTH - 1) / CB_MAX_LENGTH;
+ for (i = 0; i < nr; i++) {
+ virts[total_nr] = pci_pool_alloc(pool, GFP_KERNEL,
+ &phys[total_nr]);
+ if (!virts[total_nr]) {
+ ret = -ENOMEM;
+ goto out;
+ }
+ size = min_t(u32, chunk_len - i * CB_MAX_LENGTH,
+ CB_MAX_LENGTH);
+ memcpy(virts[total_nr], start, size);
+ start += size;
+ total_nr++;
+ /* We don't support fw chunk larger than 64*8K */
+ BUG_ON(total_nr > CB_NUMBER_OF_ELEMENTS_SMALL);
+ }
+
/* build DMA packet and queue up for sending */
/* dma to chunk->address, the chunk->length bytes from data +
* offeset*/
/* Dma loading */
- rc = ipw_fw_dma_add_buffer(priv, shared_phys + offset,
- le32_to_cpu(chunk->address),
- le32_to_cpu(chunk->length));
- if (rc) {
+ ret = ipw_fw_dma_add_buffer(priv, &phys[total_nr - nr],
+ nr, le32_to_cpu(chunk->address),
+ chunk_len);
+ if (ret) {
IPW_DEBUG_INFO("dmaAddBuffer Failed\n");
goto out;
}
- offset += le32_to_cpu(chunk->length);
+ offset += chunk_len;
} while (offset < len);
/* Run the DMA and wait for the answer */
- rc = ipw_fw_dma_kick(priv);
- if (rc) {
+ ret = ipw_fw_dma_kick(priv);
+ if (ret) {
IPW_ERROR("dmaKick Failed\n");
goto out;
}
- rc = ipw_fw_dma_wait(priv);
- if (rc) {
+ ret = ipw_fw_dma_wait(priv);
+ if (ret) {
IPW_ERROR("dmaWaitSync Failed\n");
goto out;
}
- out:
- pci_free_consistent(priv->pci_dev, len, shared_virt, shared_phys);
- return rc;
+ out:
+ for (i = 0; i < total_nr; i++)
+ pci_pool_free(pool, virts[i], phys[i]);
+
+ pci_pool_destroy(pool);
+
+ return ret;
}
/* stop nic */
--
1.5.3.6
On Thu, Aug 27, 2009 at 05:11:29PM +0800, Zhu Yi wrote:
> On Wed, 2009-08-26 at 22:44 +0800, Andrew Morton wrote:
> >
> > It is perhaps pretty simple to make the second (GFP_ATOMIC) allocation
> > go away. The code is already conveniently structured to do this:
> >
> > do {
> > chunk = (struct fw_chunk *)(data + offset);
> > offset += sizeof(struct fw_chunk);
> > /* build DMA packet and queue up for sending */
> > /* dma to chunk->address, the chunk->length bytes from
> > data +
> > * offeset*/
> > /* Dma loading */
> > rc = ipw_fw_dma_add_buffer(priv, shared_phys + offset,
> >
> > le32_to_cpu(chunk->address),
> >
> > le32_to_cpu(chunk->length));
> > if (rc) {
> > IPW_DEBUG_INFO("dmaAddBuffer Failed\n");
> > goto out;
> > }
> >
> > offset += le32_to_cpu(chunk->length);
> > } while (offset < len);
> >
> > what is the typical/expected value of chunk->length here? If it's
> > significantly less than 4096*(2^6), could we convert this function to
> > use a separate DMAable allocation per fw_chunk?
>
> Unfortunately, the largest chunk size for the latest 3.1 firmware is
> 0x20040, which also requires order 6 page allocation. I'll try to use
> the firmware DMA command block (64 slots) to handle the image (each for
> 4k, totally 256k).
>
That would be preferable as trying to make alloc-6 atomic allocations isn't
going to pan out. As I noted, doing it as GFP_KERNEL is possible but it'll
manifest as weird stalls periodically when the driver is loaded due to
reclaim and if the system is swapless, it might not work at all if memory
is mostly anonymous.
If the DMA command block doesn't work out, what is the feasibility of holding
onto the order-6 allocation once the module is loaded instead of allocing
for the duration of the firmware loading and then freeing it again?
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Wed, 2009-08-26 at 22:44 +0800, Andrew Morton wrote:
>
> It is perhaps pretty simple to make the second (GFP_ATOMIC) allocation
> go away. The code is already conveniently structured to do this:
>
> do {
> chunk = (struct fw_chunk *)(data + offset);
> offset += sizeof(struct fw_chunk);
> /* build DMA packet and queue up for sending */
> /* dma to chunk->address, the chunk->length bytes from
> data +
> * offeset*/
> /* Dma loading */
> rc = ipw_fw_dma_add_buffer(priv, shared_phys + offset,
>
> le32_to_cpu(chunk->address),
>
> le32_to_cpu(chunk->length));
> if (rc) {
> IPW_DEBUG_INFO("dmaAddBuffer Failed\n");
> goto out;
> }
>
> offset += le32_to_cpu(chunk->length);
> } while (offset < len);
>
> what is the typical/expected value of chunk->length here? If it's
> significantly less than 4096*(2^6), could we convert this function to
> use a separate DMAable allocation per fw_chunk?
Unfortunately, the largest chunk size for the latest 3.1 firmware is
0x20040, which also requires order 6 page allocation. I'll try to use
the firmware DMA command block (64 slots) to handle the image (each for
4k, totally 256k).
Thanks,
-yi
On Mon, 2009-09-21 at 12:46 +0200, Bartlomiej Zolnierkiewicz wrote:
> > > I don't know why people don't see it but for me it has a memory management
> > > regression and reliability issue written all over it.
> >
> > Possibly but drivers that reload their firmware as a response to an
> > error condition is relatively new and loading network drivers while the
> > system is already up and running a long time does not strike me as
> > typical system behaviour.
>
> Loading drivers after boot is a typical desktop/laptop behavior, please
> think about hotplug (the hardware in question is an USB dongle).
Yeah, I wonder what broke things. Did the wireless stack change in
2.6.31-rc1 too? IIRC Mel ruled out page allocator changes as a suspect.
Pekka
On Sat, Sep 19, 2009 at 03:25:32PM +0200, Bartlomiej Zolnierkiewicz wrote:
> On Wednesday 02 September 2009 20:26:17 Bartlomiej Zolnierkiewicz wrote:
> > On Wednesday 02 September 2009 20:02:14 Luis R. Rodriguez wrote:
> > > On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
> > > Zolnierkiewicz<[email protected]> wrote:
> > > > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> > > >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > > >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > > >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> > > >>
> > > >> s/2.6.30/2.6.31-rc6/
> > > >>
> > > >> The issue has always been there but it was some recent change that
> > > >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> > > >
> > > > ipw2200 fix works fine but yesterday I got the following error while mounting
> > > > ext4 filesystem (mb_history is optional so the mount succeeded):
> > >
> > > OK so the mount succeeded.
> > >
> > > > EXT4-fs (dm-2): barriers enabled
> > > > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > > > EXT4-fs (dm-2): internal journal on dm-2:8
> > > > EXT4-fs (dm-2): delayed allocation enabled
> > > > EXT4-fs: file extents enabled
> > > > mount: page allocation failure. order:5, mode:0xc0d0
> > > > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > > > Call Trace:
> > > > [<c0394de3>] ? printk+0xf/0x14
> > > > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > > > [<c016a71b>] __get_free_pages+0xf/0x32
> > > > [<c01865cf>] __kmalloc+0x28/0xfa
> > > > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > > > [<c01f529d>] ext4_mb_init+0x392/0x460
> > > > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > > > [<c0239bc8>] ? snprintf+0x15/0x17
> > > > [<c01c0b26>] ? disk_name+0x24/0x69
> > > > [<c018ba63>] get_sb_bdev+0xda/0x117
> > > > [<c01e6711>] ext4_get_sb+0x13/0x15
> > > > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > > > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > > > [<c018adad>] do_kern_mount+0x33/0xbd
> > > > [<c019d0af>] do_mount+0x660/0x6b8
> > > > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > > > [<c019d168>] sys_mount+0x61/0x99
> > > > [<c0102908>] sysenter_do_call+0x12/0x36
> > > > Mem-Info:
> > > > DMA per-cpu:
> > > > CPU 0: hi: 0, btch: 1 usd: 0
> > > > Normal per-cpu:
> > > > CPU 0: hi: 186, btch: 31 usd: 0
> > > > Active_anon:25471 active_file:22802 inactive_anon:25812
> > > > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > > > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > > > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > > > lowmem_reserve[]: 0 489 489
> > > > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > > > lowmem_reserve[]: 0 0 0
> > > > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > > > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > > > 57947 total pagecache pages
> > > > 878 pages in swap cache
> > > > Swap cache stats: add 920, delete 42, find 11/11
> > > > Free swap = 1016436kB
> > > > Total swap = 1020116kB
> > > > 131056 pages RAM
> > > > 4233 pages reserved
> > > > 90573 pages shared
> > > > 77286 pages non-shared
> > > > EXT4-fs: mballoc enabled
> > > > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> > > >
> > > > Thus it seems like the original bug is still there and any ideas how to
> > > > debug the problem further are appreciated..
> > > >
> > > > The complete dmesg and kernel config are here:
> > > >
> > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
> > >
> > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > it is the same issue, which from the trace it seems it is, then this
> > > is due to an extra kmalloc() allocation and this apparently will not
> > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > non-criticalness this issue has been deemed.
> > >
> > > A patch fix is part of the ext4-patchqueue
> > > http://repo.or.cz/w/ext4-patch-queue.git
> >
> > Thanks for the pointer but the page allocation failures that I hit seem
> > to be caused by the memory management itself and the ext4 issue fixed by:
> >
> > http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
> >
> > is a different problem (unrelated to this one).
>
> Here is another data point.
>
> This time it is an order-6 page allocation failure for rt2870sta
> (w/ upcoming driver changes) and Linus' tree from few days ago..
>
It's another high-order atomic allocation which is difficult to grant.
I didn't look closely, but is this the same type of thing - large allocation
failure during firmware loading? If so, is this during resume or is the
device being reloaded for some other reason?
I suspect that there are going to be a few of these bugs cropping up
every so often where network devices are assuming large atomic
allocations will succeed because the "only time they happen" is during
boot but these days are happening at runtime for other reasons.
> ifconfig: page allocation failure. order:6, mode:0x8020
> Pid: 4752, comm: ifconfig Tainted: G WC 2.6.31-04082-g1824090-dirty #80
> Call Trace:
> [<c03996f2>] ? printk+0xf/0x15
> [<c016b841>] __alloc_pages_nodemask+0x41d/0x462
> [<c010681e>] dma_generic_alloc_coherent+0x53/0xbd
> [<c02f83aa>] hcd_buffer_alloc+0xdb/0xe8
> [<c01067cb>] ? dma_generic_alloc_coherent+0x0/0xbd
> [<c02ee2d6>] usb_buffer_alloc+0x16/0x1d
> [<e121b627>] NICInitTransmit+0xe2/0x7e4 [rt2870sta]
> [<e121bfb1>] RTMPAllocTxRxRingMemory+0x11c/0x17b [rt2870sta]
> [<e11f0960>] rt28xx_init+0xa5/0x3f8 [rt2870sta]
> [<e121194a>] rt28xx_open+0x53/0xa2 [rt2870sta]
> [<e1211b77>] MainVirtualIF_open+0x23/0xf6 [rt2870sta]
> [<c03383a4>] dev_open+0x86/0xbb
> [<c0337b1a>] dev_change_flags+0x96/0x147
> [<c036e9cb>] devinet_ioctl+0x20f/0x4f8
> [<c036fc8f>] inet_ioctl+0x8e/0xa7
> [<c032ab50>] sock_ioctl+0x1c9/0x1ed
> [<c032a987>] ? sock_ioctl+0x0/0x1ed
> [<c0195732>] vfs_ioctl+0x18/0x71
> [<c0195cbb>] do_vfs_ioctl+0x491/0x4cf
> [<c01779d6>] ? handle_mm_fault+0x242/0x4ff
> [<c0119609>] ? do_page_fault+0x102/0x292
> [<c0140721>] ? up_read+0x16/0x29
> [<c0195d27>] sys_ioctl+0x2e/0x48
> [<c0102908>] sysenter_do_call+0x12/0x36
> Mem-Info:
> DMA per-cpu:
> CPU 0: hi: 0, btch: 1 usd: 0
> Normal per-cpu:
> CPU 0: hi: 186, btch: 31 usd: 84
> Active_anon:14664 active_file:30057 inactive_anon:31744
> inactive_file:29940 unevictable:2 dirty:11 writeback:0 unstable:0
> free:5421 slab:4037 mapped:7781 pagetables:963 bounce:0
> DMA free:2060kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:124kB active_file:3284kB inactive_file:972kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> lowmem_reserve[]: 0 489 489
> Normal free:19624kB min:2788kB low:3484kB high:4180kB active_anon:58656kB inactive_anon:126852kB active_file:116944kB inactive_file:118788kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> lowmem_reserve[]: 0 0 0
> DMA: 3*4kB 0*8kB 2*16kB 1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2060kB
> Normal: 2180*4kB 625*8kB 303*16kB 33*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 19624kB
> 64568 total pagecache pages
> 3652 pages in swap cache
> Swap cache stats: add 21642, delete 17990, find 4906/6079
> Free swap = 981700kB
> Total swap = 1020116kB
> 131056 pages RAM
> 4262 pages reserved
> 91941 pages shared
> 60834 pages non-shared
> <-- ERROR in Alloc TX TxContext[0] HTTX_BUFFER !!
> <-- RTMPAllocTxRxRingMemory, Status=3
> ERROR!!! RTMPAllocDMAMemory failed, Status[=0x00000003]
> !!! rt28xx Initialized fail !!!
>
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Mon, Sep 21, 2009 at 12:46:34PM +0200, Bartlomiej Zolnierkiewicz wrote:
> > > > > <SNIP>
> > > > >
> > > > > This time it is an order-6 page allocation failure for rt2870sta
> > > > > (w/ upcoming driver changes) and Linus' tree from few days ago..
> > > > >
> > > >
> > > > It's another high-order atomic allocation which is difficult to grant.
> > > > I didn't look closely, but is this the same type of thing - large allocation
> > > > failure during firmware loading? If so, is this during resume or is the
> > > > device being reloaded for some other reason?
> > >
> > > Just modprobing the driver on a system running for some time.
> > >
> >
> > Was this a common situation before?
>
> Yes, just like firmware restarts with ipw2200.
>
> > > > I suspect that there are going to be a few of these bugs cropping up
> > > > every so often where network devices are assuming large atomic
> > > > allocations will succeed because the "only time they happen" is during
> > > > boot but these days are happening at runtime for other reasons.
> > >
> > > I wouldn't go so far as calling a normal order-6 (256kB) allocation on
> > > 512MB machine with 1024MB swap a bug. Moreover such failures just never
> > > happened before 2.6.31-rc1.
> >
> > It's not that normal, it's an allocation that cannot sleep and cannot
> > reclaim. Why is something like firmware loading allocating memory like
>
> OK.
>
> > that? Is this use of GFP_ATOMIC relatively recent or has it always been
> > that way?
>
> It has always been like that.
>
Nuts, why is firmware loading depending on GFP_ATOMIC?
> > > I don't know why people don't see it but for me it has a memory management
> > > regression and reliability issue written all over it.
> > >
> >
> > Possibly but drivers that reload their firmware as a response to an
> > error condition is relatively new and loading network drivers while the
> > system is already up and running a long time does not strike me as
> > typical system behaviour.
>
> Loading drivers after boot is a typical desktop/laptop behavior, please
> think about hotplug (the hardware in question is an USB dongle).
>
In that case, how reproducible is this problem so it can be
bisected? Basically, there are no guarantees that GFP_ATOMIC allocations
of this order will succeed although you can improve the odds by increasing
min_free_kbytes. Network drivers should never have been depending on GFP_ATOMIC
succeeding like this but the hole has been dug now.
If it's happening more frequently now than it used to then either
1. The allocations are occuring more frequently where as previously a
pool might have been reused or the memory not freed for the lifetime of
the system.
2. Something has changed in the allocator. I'm not aware of recent
changes that could cause this though in such a recent time-frame.
3. Something has changed recently with respect to reclaim. There have
been changes made recently to lumpy reclaim and that might be impacting
kswapd's efforts at keeping large contiguous regions free.
4. Hotplug events that involve driver loads are more common now than they
were previously for some reason. You mention that this is a USB dongle for
example. Was it a case before that the driver loaded early and remained
resident but only active after a hotplug event? If that was the case,
the memory would be allocated once at boot. However, if an optimisation
made recently unloads those unused drivers and re-loads them later, there
would be more order-6 allocations than they were previously and manifest
as these bug reports. Is this a possibility?
The ideal would be that network drivers not make allocations like this
in the first place by, for example, DMAing the firmware across in
page-size chunks instead of one contiguous lump :/
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Wed, Sep 02, 2009 at 11:02:14AM -0700, Luis R. Rodriguez wrote:
> On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
> Zolnierkiewicz<[email protected]> wrote:
> > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> >>
> >> s/2.6.30/2.6.31-rc6/
> >>
> >> The issue has always been there but it was some recent change that
> >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> >
> > ipw2200 fix works fine but yesterday I got the following error while mounting
> > ext4 filesystem (mb_history is optional so the mount succeeded):
>
> OK so the mount succeeded.
>
> > EXT4-fs (dm-2): barriers enabled
> > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > EXT4-fs (dm-2): internal journal on dm-2:8
> > EXT4-fs (dm-2): delayed allocation enabled
> > EXT4-fs: file extents enabled
> > mount: page allocation failure. order:5, mode:0xc0d0
> > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > Call Trace:
> > ?[<c0394de3>] ? printk+0xf/0x14
> > ?[<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > ?[<c016a71b>] __get_free_pages+0xf/0x32
> > ?[<c01865cf>] __kmalloc+0x28/0xfa
> > ?[<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > ?[<c01f529d>] ext4_mb_init+0x392/0x460
> > ?[<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > ?[<c0239bc8>] ? snprintf+0x15/0x17
> > ?[<c01c0b26>] ? disk_name+0x24/0x69
> > ?[<c018ba63>] get_sb_bdev+0xda/0x117
> > ?[<c01e6711>] ext4_get_sb+0x13/0x15
> > ?[<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > ?[<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > ?[<c018adad>] do_kern_mount+0x33/0xbd
> > ?[<c019d0af>] do_mount+0x660/0x6b8
> > ?[<c016a71b>] ? __get_free_pages+0xf/0x32
> > ?[<c019d168>] sys_mount+0x61/0x99
> > ?[<c0102908>] sysenter_do_call+0x12/0x36
> > Mem-Info:
> > DMA per-cpu:
> > CPU ? ?0: hi: ? ?0, btch: ? 1 usd: ? 0
> > Normal per-cpu:
> > CPU ? ?0: hi: ?186, btch: ?31 usd: ? 0
> > Active_anon:25471 active_file:22802 inactive_anon:25812
> > ?inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > ?free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > lowmem_reserve[]: 0 489 489
> > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > lowmem_reserve[]: 0 0 0
> > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > 57947 total pagecache pages
> > 878 pages in swap cache
> > Swap cache stats: add 920, delete 42, find 11/11
> > Free swap ?= 1016436kB
> > Total swap = 1020116kB
> > 131056 pages RAM
> > 4233 pages reserved
> > 90573 pages shared
> > 77286 pages non-shared
> > EXT4-fs: mballoc enabled
> > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> >
> > Thus it seems like the original bug is still there and any ideas how to
> > debug the problem further are appreciated..
> >
> > The complete dmesg and kernel config are here:
> >
> > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
>
> This looks very similar to the kmemleak ext4 reports upon a mount. If
> it is the same issue, which from the trace it seems it is, then this
> is due to an extra kmalloc() allocation and this apparently will not
> get fixed on 2.6.31 due to the closeness of the merge window and the
> non-criticalness this issue has been deemed.
>
I suspect the more pressing concern is why is this kmalloc() resulting in
an order-5 allocation request? What size is the buffer being requested?
Was that expected? What is the contents of /proc/slabinfo in case a buffer
that should have required order-1 or order-2 is using a higher order for
some reason.
> A patch fix is part of the ext4-patchqueue
> http://repo.or.cz/w/ext4-patch-queue.git
>
p.s. I'm will be offline until Tuesday so will not be initially very
responsive.
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Mon, Sep 21, 2009 at 11:59:27AM +0200, Bartlomiej Zolnierkiewicz wrote:
> > > > > > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> > > > > >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > > > > >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > > > > >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> > > > > >>
> > > > > >> s/2.6.30/2.6.31-rc6/
> > > > > >>
> > > > > >> The issue has always been there but it was some recent change that
> > > > > >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> > > > > >
> > > > > > ipw2200 fix works fine but yesterday I got the following error while mounting
> > > > > > ext4 filesystem (mb_history is optional so the mount succeeded):
> > > > >
> > > > > OK so the mount succeeded.
> > > > >
> > > > > > EXT4-fs (dm-2): barriers enabled
> > > > > > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > > > > > EXT4-fs (dm-2): internal journal on dm-2:8
> > > > > > EXT4-fs (dm-2): delayed allocation enabled
> > > > > > EXT4-fs: file extents enabled
> > > > > > mount: page allocation failure. order:5, mode:0xc0d0
> > > > > > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > > > > > Call Trace:
> > > > > > [<c0394de3>] ? printk+0xf/0x14
> > > > > > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > > > > > [<c016a71b>] __get_free_pages+0xf/0x32
> > > > > > [<c01865cf>] __kmalloc+0x28/0xfa
> > > > > > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > > > > > [<c01f529d>] ext4_mb_init+0x392/0x460
> > > > > > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > > > > > [<c0239bc8>] ? snprintf+0x15/0x17
> > > > > > [<c01c0b26>] ? disk_name+0x24/0x69
> > > > > > [<c018ba63>] get_sb_bdev+0xda/0x117
> > > > > > [<c01e6711>] ext4_get_sb+0x13/0x15
> > > > > > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > > > > > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > > > > > [<c018adad>] do_kern_mount+0x33/0xbd
> > > > > > [<c019d0af>] do_mount+0x660/0x6b8
> > > > > > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > > > > > [<c019d168>] sys_mount+0x61/0x99
> > > > > > [<c0102908>] sysenter_do_call+0x12/0x36
> > > > > > Mem-Info:
> > > > > > DMA per-cpu:
> > > > > > CPU 0: hi: 0, btch: 1 usd: 0
> > > > > > Normal per-cpu:
> > > > > > CPU 0: hi: 186, btch: 31 usd: 0
> > > > > > Active_anon:25471 active_file:22802 inactive_anon:25812
> > > > > > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > > > > > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > > > > > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > > > > > lowmem_reserve[]: 0 489 489
> > > > > > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > > > > > lowmem_reserve[]: 0 0 0
> > > > > > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > > > > > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > > > > > 57947 total pagecache pages
> > > > > > 878 pages in swap cache
> > > > > > Swap cache stats: add 920, delete 42, find 11/11
> > > > > > Free swap = 1016436kB
> > > > > > Total swap = 1020116kB
> > > > > > 131056 pages RAM
> > > > > > 4233 pages reserved
> > > > > > 90573 pages shared
> > > > > > 77286 pages non-shared
> > > > > > EXT4-fs: mballoc enabled
> > > > > > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> > > > > >
> > > > > > Thus it seems like the original bug is still there and any ideas how to
> > > > > > debug the problem further are appreciated..
> > > > > >
> > > > > > The complete dmesg and kernel config are here:
> > > > > >
> > > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
> > > > >
> > > > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > > > it is the same issue, which from the trace it seems it is, then this
> > > > > is due to an extra kmalloc() allocation and this apparently will not
> > > > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > > > non-criticalness this issue has been deemed.
> > > > >
> > > > > A patch fix is part of the ext4-patchqueue
> > > > > http://repo.or.cz/w/ext4-patch-queue.git
> > > >
> > > > Thanks for the pointer but the page allocation failures that I hit seem
> > > > to be caused by the memory management itself and the ext4 issue fixed by:
> > > >
> > > > http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
> > > >
> > > > is a different problem (unrelated to this one).
> > >
> > > Here is another data point.
> > >
> > > This time it is an order-6 page allocation failure for rt2870sta
> > > (w/ upcoming driver changes) and Linus' tree from few days ago..
> > >
> >
> > It's another high-order atomic allocation which is difficult to grant.
> > I didn't look closely, but is this the same type of thing - large allocation
> > failure during firmware loading? If so, is this during resume or is the
> > device being reloaded for some other reason?
>
> Just modprobing the driver on a system running for some time.
>
Was this a common situation before?
> > I suspect that there are going to be a few of these bugs cropping up
> > every so often where network devices are assuming large atomic
> > allocations will succeed because the "only time they happen" is during
> > boot but these days are happening at runtime for other reasons.
>
> I wouldn't go so far as calling a normal order-6 (256kB) allocation on
> 512MB machine with 1024MB swap a bug. Moreover such failures just never
> happened before 2.6.31-rc1.
It's not that normal, it's an allocation that cannot sleep and cannot
reclaim. Why is something like firmware loading allocating memory like
that? Is this use of GFP_ATOMIC relatively recent or has it always been
that way?
> I don't know why people don't see it but for me it has a memory management
> regression and reliability issue written all over it.
>
Possibly but drivers that reload their firmware as a response to an
error condition is relatively new and loading network drivers while the
system is already up and running a long time does not strike me as
typical system behaviour.
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Sat, Sep 05, 2009 at 10:28:37AM -0400, Theodore Tso wrote:
> On Thu, Sep 03, 2009 at 01:49:14PM +0100, Mel Gorman wrote:
> > >
> > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > it is the same issue, which from the trace it seems it is, then this
> > > is due to an extra kmalloc() allocation and this apparently will not
> > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > non-criticalness this issue has been deemed.
>
> No, it's a different problem.
>
> > I suspect the more pressing concern is why is this kmalloc() resulting in
> > an order-5 allocation request? What size is the buffer being requested?
> > Was that expected? What is the contents of /proc/slabinfo in case a buffer
> > that should have required order-1 or order-2 is using a higher order for
> > some reason.
>
> It's allocating 68,000 bytes for the mb_history structure, which is
> used for debugging purposes. That's why it's optional and we continue
> if it's not allocated. We should fix it to use vmalloc()
You could call with kmalloc(FLAGS|GFP_NOWARN) with a fallback to
vmalloc() and a disable if vmalloc() fails as well. Maybe check out what
kernel/profile.c#profile_init() to allocate a large buffer and do something
similar?
> and I'm
> inclined to turn it off by default since it's not worth the overhead,
> and most ext4 users won't find it useful or interesting.
>
I can't comment as I don't know what sort of debugging it's useful for.
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Wednesday 02 September 2009 20:02:14 Luis R. Rodriguez wrote:
> On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
> Zolnierkiewicz<[email protected]> wrote:
> > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> >>
> >> s/2.6.30/2.6.31-rc6/
> >>
> >> The issue has always been there but it was some recent change that
> >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> >
> > ipw2200 fix works fine but yesterday I got the following error while mounting
> > ext4 filesystem (mb_history is optional so the mount succeeded):
>
> OK so the mount succeeded.
>
> > EXT4-fs (dm-2): barriers enabled
> > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > EXT4-fs (dm-2): internal journal on dm-2:8
> > EXT4-fs (dm-2): delayed allocation enabled
> > EXT4-fs: file extents enabled
> > mount: page allocation failure. order:5, mode:0xc0d0
> > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > Call Trace:
> > [<c0394de3>] ? printk+0xf/0x14
> > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > [<c016a71b>] __get_free_pages+0xf/0x32
> > [<c01865cf>] __kmalloc+0x28/0xfa
> > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > [<c01f529d>] ext4_mb_init+0x392/0x460
> > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > [<c0239bc8>] ? snprintf+0x15/0x17
> > [<c01c0b26>] ? disk_name+0x24/0x69
> > [<c018ba63>] get_sb_bdev+0xda/0x117
> > [<c01e6711>] ext4_get_sb+0x13/0x15
> > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > [<c018adad>] do_kern_mount+0x33/0xbd
> > [<c019d0af>] do_mount+0x660/0x6b8
> > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > [<c019d168>] sys_mount+0x61/0x99
> > [<c0102908>] sysenter_do_call+0x12/0x36
> > Mem-Info:
> > DMA per-cpu:
> > CPU 0: hi: 0, btch: 1 usd: 0
> > Normal per-cpu:
> > CPU 0: hi: 186, btch: 31 usd: 0
> > Active_anon:25471 active_file:22802 inactive_anon:25812
> > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > lowmem_reserve[]: 0 489 489
> > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > lowmem_reserve[]: 0 0 0
> > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > 57947 total pagecache pages
> > 878 pages in swap cache
> > Swap cache stats: add 920, delete 42, find 11/11
> > Free swap = 1016436kB
> > Total swap = 1020116kB
> > 131056 pages RAM
> > 4233 pages reserved
> > 90573 pages shared
> > 77286 pages non-shared
> > EXT4-fs: mballoc enabled
> > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> >
> > Thus it seems like the original bug is still there and any ideas how to
> > debug the problem further are appreciated..
> >
> > The complete dmesg and kernel config are here:
> >
> > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
>
> This looks very similar to the kmemleak ext4 reports upon a mount. If
> it is the same issue, which from the trace it seems it is, then this
> is due to an extra kmalloc() allocation and this apparently will not
> get fixed on 2.6.31 due to the closeness of the merge window and the
> non-criticalness this issue has been deemed.
>
> A patch fix is part of the ext4-patchqueue
> http://repo.or.cz/w/ext4-patch-queue.git
Thanks for the pointer but the page allocation failures that I hit seem
to be caused by the memory management itself and the ext4 issue fixed by:
http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
is a different problem (unrelated to this one).
On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
>
> s/2.6.30/2.6.31-rc6/
>
> The issue has always been there but it was some recent change that
> explicitly triggered the allocation failures (after 2.6.31-rc1).
ipw2200 fix works fine but yesterday I got the following error while mounting
ext4 filesystem (mb_history is optional so the mount succeeded):
EXT4-fs (dm-2): barriers enabled
kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
EXT4-fs (dm-2): internal journal on dm-2:8
EXT4-fs (dm-2): delayed allocation enabled
EXT4-fs: file extents enabled
mount: page allocation failure. order:5, mode:0xc0d0
Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
Call Trace:
[<c0394de3>] ? printk+0xf/0x14
[<c016a693>] __alloc_pages_nodemask+0x400/0x442
[<c016a71b>] __get_free_pages+0xf/0x32
[<c01865cf>] __kmalloc+0x28/0xfa
[<c023d96f>] ? __spin_lock_init+0x28/0x4d
[<c01f529d>] ext4_mb_init+0x392/0x460
[<c01e99d2>] ext4_fill_super+0x1b96/0x2012
[<c0239bc8>] ? snprintf+0x15/0x17
[<c01c0b26>] ? disk_name+0x24/0x69
[<c018ba63>] get_sb_bdev+0xda/0x117
[<c01e6711>] ext4_get_sb+0x13/0x15
[<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
[<c018ad2d>] vfs_kern_mount+0x3b/0x76
[<c018adad>] do_kern_mount+0x33/0xbd
[<c019d0af>] do_mount+0x660/0x6b8
[<c016a71b>] ? __get_free_pages+0xf/0x32
[<c019d168>] sys_mount+0x61/0x99
[<c0102908>] sysenter_do_call+0x12/0x36
Mem-Info:
DMA per-cpu:
CPU 0: hi: 0, btch: 1 usd: 0
Normal per-cpu:
CPU 0: hi: 186, btch: 31 usd: 0
Active_anon:25471 active_file:22802 inactive_anon:25812
inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 489 489
Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0
DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
57947 total pagecache pages
878 pages in swap cache
Swap cache stats: add 920, delete 42, find 11/11
Free swap = 1016436kB
Total swap = 1020116kB
131056 pages RAM
4233 pages reserved
90573 pages shared
77286 pages non-shared
EXT4-fs: mballoc enabled
EXT4-fs (dm-2): mounted filesystem with ordered data mode
Thus it seems like the original bug is still there and any ideas how to
debug the problem further are appreciated..
The complete dmesg and kernel config are here:
http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
On Thu, Sep 03, 2009 at 01:49:14PM +0100, Mel Gorman wrote:
> >
> > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > it is the same issue, which from the trace it seems it is, then this
> > is due to an extra kmalloc() allocation and this apparently will not
> > get fixed on 2.6.31 due to the closeness of the merge window and the
> > non-criticalness this issue has been deemed.
No, it's a different problem.
> I suspect the more pressing concern is why is this kmalloc() resulting in
> an order-5 allocation request? What size is the buffer being requested?
> Was that expected? What is the contents of /proc/slabinfo in case a buffer
> that should have required order-1 or order-2 is using a higher order for
> some reason.
It's allocating 68,000 bytes for the mb_history structure, which is
used for debugging purposes. That's why it's optional and we continue
if it's not allocated. We should fix it to use vmalloc() and I'm
inclined to turn it off by default since it's not worth the overhead,
and most ext4 users won't find it useful or interesting.
- Ted
On Wednesday 02 September 2009 20:26:17 Bartlomiej Zolnierkiewicz wrote:
> On Wednesday 02 September 2009 20:02:14 Luis R. Rodriguez wrote:
> > On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
> > Zolnierkiewicz<[email protected]> wrote:
> > > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> > >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> > >>
> > >> s/2.6.30/2.6.31-rc6/
> > >>
> > >> The issue has always been there but it was some recent change that
> > >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> > >
> > > ipw2200 fix works fine but yesterday I got the following error while mounting
> > > ext4 filesystem (mb_history is optional so the mount succeeded):
> >
> > OK so the mount succeeded.
> >
> > > EXT4-fs (dm-2): barriers enabled
> > > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > > EXT4-fs (dm-2): internal journal on dm-2:8
> > > EXT4-fs (dm-2): delayed allocation enabled
> > > EXT4-fs: file extents enabled
> > > mount: page allocation failure. order:5, mode:0xc0d0
> > > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > > Call Trace:
> > > [<c0394de3>] ? printk+0xf/0x14
> > > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > > [<c016a71b>] __get_free_pages+0xf/0x32
> > > [<c01865cf>] __kmalloc+0x28/0xfa
> > > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > > [<c01f529d>] ext4_mb_init+0x392/0x460
> > > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > > [<c0239bc8>] ? snprintf+0x15/0x17
> > > [<c01c0b26>] ? disk_name+0x24/0x69
> > > [<c018ba63>] get_sb_bdev+0xda/0x117
> > > [<c01e6711>] ext4_get_sb+0x13/0x15
> > > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > > [<c018adad>] do_kern_mount+0x33/0xbd
> > > [<c019d0af>] do_mount+0x660/0x6b8
> > > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > > [<c019d168>] sys_mount+0x61/0x99
> > > [<c0102908>] sysenter_do_call+0x12/0x36
> > > Mem-Info:
> > > DMA per-cpu:
> > > CPU 0: hi: 0, btch: 1 usd: 0
> > > Normal per-cpu:
> > > CPU 0: hi: 186, btch: 31 usd: 0
> > > Active_anon:25471 active_file:22802 inactive_anon:25812
> > > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > > lowmem_reserve[]: 0 489 489
> > > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > > lowmem_reserve[]: 0 0 0
> > > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > > 57947 total pagecache pages
> > > 878 pages in swap cache
> > > Swap cache stats: add 920, delete 42, find 11/11
> > > Free swap = 1016436kB
> > > Total swap = 1020116kB
> > > 131056 pages RAM
> > > 4233 pages reserved
> > > 90573 pages shared
> > > 77286 pages non-shared
> > > EXT4-fs: mballoc enabled
> > > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> > >
> > > Thus it seems like the original bug is still there and any ideas how to
> > > debug the problem further are appreciated..
> > >
> > > The complete dmesg and kernel config are here:
> > >
> > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
> >
> > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > it is the same issue, which from the trace it seems it is, then this
> > is due to an extra kmalloc() allocation and this apparently will not
> > get fixed on 2.6.31 due to the closeness of the merge window and the
> > non-criticalness this issue has been deemed.
> >
> > A patch fix is part of the ext4-patchqueue
> > http://repo.or.cz/w/ext4-patch-queue.git
>
> Thanks for the pointer but the page allocation failures that I hit seem
> to be caused by the memory management itself and the ext4 issue fixed by:
>
> http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
>
> is a different problem (unrelated to this one).
Here is another data point.
This time it is an order-6 page allocation failure for rt2870sta
(w/ upcoming driver changes) and Linus' tree from few days ago..
ifconfig: page allocation failure. order:6, mode:0x8020
Pid: 4752, comm: ifconfig Tainted: G WC 2.6.31-04082-g1824090-dirty #80
Call Trace:
[<c03996f2>] ? printk+0xf/0x15
[<c016b841>] __alloc_pages_nodemask+0x41d/0x462
[<c010681e>] dma_generic_alloc_coherent+0x53/0xbd
[<c02f83aa>] hcd_buffer_alloc+0xdb/0xe8
[<c01067cb>] ? dma_generic_alloc_coherent+0x0/0xbd
[<c02ee2d6>] usb_buffer_alloc+0x16/0x1d
[<e121b627>] NICInitTransmit+0xe2/0x7e4 [rt2870sta]
[<e121bfb1>] RTMPAllocTxRxRingMemory+0x11c/0x17b [rt2870sta]
[<e11f0960>] rt28xx_init+0xa5/0x3f8 [rt2870sta]
[<e121194a>] rt28xx_open+0x53/0xa2 [rt2870sta]
[<e1211b77>] MainVirtualIF_open+0x23/0xf6 [rt2870sta]
[<c03383a4>] dev_open+0x86/0xbb
[<c0337b1a>] dev_change_flags+0x96/0x147
[<c036e9cb>] devinet_ioctl+0x20f/0x4f8
[<c036fc8f>] inet_ioctl+0x8e/0xa7
[<c032ab50>] sock_ioctl+0x1c9/0x1ed
[<c032a987>] ? sock_ioctl+0x0/0x1ed
[<c0195732>] vfs_ioctl+0x18/0x71
[<c0195cbb>] do_vfs_ioctl+0x491/0x4cf
[<c01779d6>] ? handle_mm_fault+0x242/0x4ff
[<c0119609>] ? do_page_fault+0x102/0x292
[<c0140721>] ? up_read+0x16/0x29
[<c0195d27>] sys_ioctl+0x2e/0x48
[<c0102908>] sysenter_do_call+0x12/0x36
Mem-Info:
DMA per-cpu:
CPU 0: hi: 0, btch: 1 usd: 0
Normal per-cpu:
CPU 0: hi: 186, btch: 31 usd: 84
Active_anon:14664 active_file:30057 inactive_anon:31744
inactive_file:29940 unevictable:2 dirty:11 writeback:0 unstable:0
free:5421 slab:4037 mapped:7781 pagetables:963 bounce:0
DMA free:2060kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:124kB active_file:3284kB inactive_file:972kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 489 489
Normal free:19624kB min:2788kB low:3484kB high:4180kB active_anon:58656kB inactive_anon:126852kB active_file:116944kB inactive_file:118788kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 0
DMA: 3*4kB 0*8kB 2*16kB 1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2060kB
Normal: 2180*4kB 625*8kB 303*16kB 33*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 19624kB
64568 total pagecache pages
3652 pages in swap cache
Swap cache stats: add 21642, delete 17990, find 4906/6079
Free swap = 981700kB
Total swap = 1020116kB
131056 pages RAM
4262 pages reserved
91941 pages shared
60834 pages non-shared
<-- ERROR in Alloc TX TxContext[0] HTTX_BUFFER !!
<-- RTMPAllocTxRxRingMemory, Status=3
ERROR!!! RTMPAllocDMAMemory failed, Status[=0x00000003]
!!! rt28xx Initialized fail !!!
On Mon, Sep 21, 2009 at 03:12:14PM +0200, Bartlomiej Zolnierkiewicz wrote:
> On Monday 21 September 2009 12:56:48 Pekka Enberg wrote:
> > On Mon, 2009-09-21 at 12:46 +0200, Bartlomiej Zolnierkiewicz wrote:
> > > > > I don't know why people don't see it but for me it has a memory management
> > > > > regression and reliability issue written all over it.
> > > >
> > > > Possibly but drivers that reload their firmware as a response to an
> > > > error condition is relatively new and loading network drivers while the
> > > > system is already up and running a long time does not strike me as
> > > > typical system behaviour.
> > >
> > > Loading drivers after boot is a typical desktop/laptop behavior, please
> > > think about hotplug (the hardware in question is an USB dongle).
> >
> > Yeah, I wonder what broke things. Did the wireless stack change in
> > 2.6.31-rc1 too? IIRC Mel ruled out page allocator changes as a suspect.
>
> The thing is that the mm behavior change has been narrowed down already
> over a month ago to -mm merge in 2.6.31-rc1 (as has been noted in my initial
> reports), I first though that that it was -next breakage but it turned out
> that it came the other way around (because -mm is not even pulled into -next
> currently -- great way to set an example for other kernel maintainers BTW).
>
Is there a reliable reproduction case for this that narrowed it down to
2.6.31-rc1? That is the window where a number of page-allocator optimisation
patches made it in. None of them should have affected the allocator from a
fragmentation perspective though.
If you have a reliable reproduction case, testing between commits
d239171e4f6efd58d7e423853056b1b6a74f1446..a1dd268cf6306565a31a48deff8bf4f6b4b105f7
would be nice, particularly if it can be bisected within that small
window rather than a full bisect of an rc1 which I know can be a major
mess.
> I understand that behavior change may be justified and technically correct
> in itself. I also completely agree that high order allocations in certain
> drivers need fixing anyway.
>
> However there is something wrong with the big picture and the way changes
> are happening. I'm not saying that I'm surprised though, especially given
> the recent decline in the quality assurance and the paradigm shift that
> I'm seeing (some influential top level people talking that -rc1 is fine for
> testing new code now or the "new kernel new hardware" thing).
>
The quality assurance comment is a bit unfair with respect to the page
allocator. There are a lot of things that can have changed that would hose
order-6 atomic allocations. Furthermore, test cases used for mm patches
would not have taken into account such allocations as being critical. Even
if it was considered, it would have been dismissed as "it makes no sense
for drivers to be doing order-6 GFP_ATOMIC" allocations.
> Sorry but I have no more time currently to narrow down the issue some more
> (guess what, there are other kernel bugs standing in the way to bisect it
> and I would have to provide some reliable way to reproduce it first) so I
> see no more point in wasting people's time on this. I can certainly get by
> with allocation failure here and there. Not a big deal for me personally..
>
That is somewhat unfortunate. Even testing within the window above if
possible would be very helpful if you get the chance.
--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab
On Tue, 2009-09-08 at 12:00 +0100, Mel Gorman wrote:
> On Sat, Sep 05, 2009 at 10:28:37AM -0400, Theodore Tso wrote:
> > On Thu, Sep 03, 2009 at 01:49:14PM +0100, Mel Gorman wrote:
> > > >
> > > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > > it is the same issue, which from the trace it seems it is, then this
> > > > is due to an extra kmalloc() allocation and this apparently will not
> > > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > > non-criticalness this issue has been deemed.
> >
> > No, it's a different problem.
> >
> > > I suspect the more pressing concern is why is this kmalloc() resulting in
> > > an order-5 allocation request? What size is the buffer being requested?
> > > Was that expected? What is the contents of /proc/slabinfo in case a buffer
> > > that should have required order-1 or order-2 is using a higher order for
> > > some reason.
> >
> > It's allocating 68,000 bytes for the mb_history structure, which is
> > used for debugging purposes. That's why it's optional and we continue
> > if it's not allocated. We should fix it to use vmalloc()
>
> You could call with kmalloc(FLAGS|GFP_NOWARN) with a fallback to
> vmalloc() and a disable if vmalloc() fails as well. Maybe check out what
> kernel/profile.c#profile_init() to allocate a large buffer and do something
> similar?
>
> > and I'm
> > inclined to turn it off by default since it's not worth the overhead,
> > and most ext4 users won't find it useful or interesting.
> >
>
> I can't comment as I don't know what sort of debugging it's useful for.
>
Perhaps this is a suitable use for the new proposed flex_array? From an
initial glance, I can't see why the allocated memory has to be
contiguous..
http://lwn.net/Articles/345273/
Cheers, Simon
On Monday 21 September 2009 10:58:44 Mel Gorman wrote:
> On Sat, Sep 19, 2009 at 03:25:32PM +0200, Bartlomiej Zolnierkiewicz wrote:
> > On Wednesday 02 September 2009 20:26:17 Bartlomiej Zolnierkiewicz wrote:
> > > On Wednesday 02 September 2009 20:02:14 Luis R. Rodriguez wrote:
> > > > On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
> > > > Zolnierkiewicz<[email protected]> wrote:
> > > > > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> > > > >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > > > >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > > > >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> > > > >>
> > > > >> s/2.6.30/2.6.31-rc6/
> > > > >>
> > > > >> The issue has always been there but it was some recent change that
> > > > >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> > > > >
> > > > > ipw2200 fix works fine but yesterday I got the following error while mounting
> > > > > ext4 filesystem (mb_history is optional so the mount succeeded):
> > > >
> > > > OK so the mount succeeded.
> > > >
> > > > > EXT4-fs (dm-2): barriers enabled
> > > > > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > > > > EXT4-fs (dm-2): internal journal on dm-2:8
> > > > > EXT4-fs (dm-2): delayed allocation enabled
> > > > > EXT4-fs: file extents enabled
> > > > > mount: page allocation failure. order:5, mode:0xc0d0
> > > > > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > > > > Call Trace:
> > > > > [<c0394de3>] ? printk+0xf/0x14
> > > > > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > > > > [<c016a71b>] __get_free_pages+0xf/0x32
> > > > > [<c01865cf>] __kmalloc+0x28/0xfa
> > > > > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > > > > [<c01f529d>] ext4_mb_init+0x392/0x460
> > > > > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > > > > [<c0239bc8>] ? snprintf+0x15/0x17
> > > > > [<c01c0b26>] ? disk_name+0x24/0x69
> > > > > [<c018ba63>] get_sb_bdev+0xda/0x117
> > > > > [<c01e6711>] ext4_get_sb+0x13/0x15
> > > > > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > > > > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > > > > [<c018adad>] do_kern_mount+0x33/0xbd
> > > > > [<c019d0af>] do_mount+0x660/0x6b8
> > > > > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > > > > [<c019d168>] sys_mount+0x61/0x99
> > > > > [<c0102908>] sysenter_do_call+0x12/0x36
> > > > > Mem-Info:
> > > > > DMA per-cpu:
> > > > > CPU 0: hi: 0, btch: 1 usd: 0
> > > > > Normal per-cpu:
> > > > > CPU 0: hi: 186, btch: 31 usd: 0
> > > > > Active_anon:25471 active_file:22802 inactive_anon:25812
> > > > > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > > > > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > > > > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > > > > lowmem_reserve[]: 0 489 489
> > > > > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > > > > lowmem_reserve[]: 0 0 0
> > > > > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > > > > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > > > > 57947 total pagecache pages
> > > > > 878 pages in swap cache
> > > > > Swap cache stats: add 920, delete 42, find 11/11
> > > > > Free swap = 1016436kB
> > > > > Total swap = 1020116kB
> > > > > 131056 pages RAM
> > > > > 4233 pages reserved
> > > > > 90573 pages shared
> > > > > 77286 pages non-shared
> > > > > EXT4-fs: mballoc enabled
> > > > > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> > > > >
> > > > > Thus it seems like the original bug is still there and any ideas how to
> > > > > debug the problem further are appreciated..
> > > > >
> > > > > The complete dmesg and kernel config are here:
> > > > >
> > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
> > > >
> > > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > > it is the same issue, which from the trace it seems it is, then this
> > > > is due to an extra kmalloc() allocation and this apparently will not
> > > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > > non-criticalness this issue has been deemed.
> > > >
> > > > A patch fix is part of the ext4-patchqueue
> > > > http://repo.or.cz/w/ext4-patch-queue.git
> > >
> > > Thanks for the pointer but the page allocation failures that I hit seem
> > > to be caused by the memory management itself and the ext4 issue fixed by:
> > >
> > > http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
> > >
> > > is a different problem (unrelated to this one).
> >
> > Here is another data point.
> >
> > This time it is an order-6 page allocation failure for rt2870sta
> > (w/ upcoming driver changes) and Linus' tree from few days ago..
> >
>
> It's another high-order atomic allocation which is difficult to grant.
> I didn't look closely, but is this the same type of thing - large allocation
> failure during firmware loading? If so, is this during resume or is the
> device being reloaded for some other reason?
Just modprobing the driver on a system running for some time.
> I suspect that there are going to be a few of these bugs cropping up
> every so often where network devices are assuming large atomic
> allocations will succeed because the "only time they happen" is during
> boot but these days are happening at runtime for other reasons.
I wouldn't go so far as calling a normal order-6 (256kB) allocation on
512MB machine with 1024MB swap a bug. Moreover such failures just never
happened before 2.6.31-rc1.
I don't know why people don't see it but for me it has a memory management
regression and reliability issue written all over it.
On Monday 21 September 2009 12:08:13 Mel Gorman wrote:
> On Mon, Sep 21, 2009 at 11:59:27AM +0200, Bartlomiej Zolnierkiewicz wrote:
> > > > > > > On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
> > > > > > >> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
> > > > > > >> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
> > > > > > >> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
> > > > > > >>
> > > > > > >> s/2.6.30/2.6.31-rc6/
> > > > > > >>
> > > > > > >> The issue has always been there but it was some recent change that
> > > > > > >> explicitly triggered the allocation failures (after 2.6.31-rc1).
> > > > > > >
> > > > > > > ipw2200 fix works fine but yesterday I got the following error while mounting
> > > > > > > ext4 filesystem (mb_history is optional so the mount succeeded):
> > > > > >
> > > > > > OK so the mount succeeded.
> > > > > >
> > > > > > > EXT4-fs (dm-2): barriers enabled
> > > > > > > kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> > > > > > > EXT4-fs (dm-2): internal journal on dm-2:8
> > > > > > > EXT4-fs (dm-2): delayed allocation enabled
> > > > > > > EXT4-fs: file extents enabled
> > > > > > > mount: page allocation failure. order:5, mode:0xc0d0
> > > > > > > Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> > > > > > > Call Trace:
> > > > > > > [<c0394de3>] ? printk+0xf/0x14
> > > > > > > [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> > > > > > > [<c016a71b>] __get_free_pages+0xf/0x32
> > > > > > > [<c01865cf>] __kmalloc+0x28/0xfa
> > > > > > > [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> > > > > > > [<c01f529d>] ext4_mb_init+0x392/0x460
> > > > > > > [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> > > > > > > [<c0239bc8>] ? snprintf+0x15/0x17
> > > > > > > [<c01c0b26>] ? disk_name+0x24/0x69
> > > > > > > [<c018ba63>] get_sb_bdev+0xda/0x117
> > > > > > > [<c01e6711>] ext4_get_sb+0x13/0x15
> > > > > > > [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> > > > > > > [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> > > > > > > [<c018adad>] do_kern_mount+0x33/0xbd
> > > > > > > [<c019d0af>] do_mount+0x660/0x6b8
> > > > > > > [<c016a71b>] ? __get_free_pages+0xf/0x32
> > > > > > > [<c019d168>] sys_mount+0x61/0x99
> > > > > > > [<c0102908>] sysenter_do_call+0x12/0x36
> > > > > > > Mem-Info:
> > > > > > > DMA per-cpu:
> > > > > > > CPU 0: hi: 0, btch: 1 usd: 0
> > > > > > > Normal per-cpu:
> > > > > > > CPU 0: hi: 186, btch: 31 usd: 0
> > > > > > > Active_anon:25471 active_file:22802 inactive_anon:25812
> > > > > > > inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> > > > > > > free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> > > > > > > DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> > > > > > > lowmem_reserve[]: 0 489 489
> > > > > > > Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> > > > > > > lowmem_reserve[]: 0 0 0
> > > > > > > DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> > > > > > > Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> > > > > > > 57947 total pagecache pages
> > > > > > > 878 pages in swap cache
> > > > > > > Swap cache stats: add 920, delete 42, find 11/11
> > > > > > > Free swap = 1016436kB
> > > > > > > Total swap = 1020116kB
> > > > > > > 131056 pages RAM
> > > > > > > 4233 pages reserved
> > > > > > > 90573 pages shared
> > > > > > > 77286 pages non-shared
> > > > > > > EXT4-fs: mballoc enabled
> > > > > > > EXT4-fs (dm-2): mounted filesystem with ordered data mode
> > > > > > >
> > > > > > > Thus it seems like the original bug is still there and any ideas how to
> > > > > > > debug the problem further are appreciated..
> > > > > > >
> > > > > > > The complete dmesg and kernel config are here:
> > > > > > >
> > > > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> > > > > > > http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
> > > > > >
> > > > > > This looks very similar to the kmemleak ext4 reports upon a mount. If
> > > > > > it is the same issue, which from the trace it seems it is, then this
> > > > > > is due to an extra kmalloc() allocation and this apparently will not
> > > > > > get fixed on 2.6.31 due to the closeness of the merge window and the
> > > > > > non-criticalness this issue has been deemed.
> > > > > >
> > > > > > A patch fix is part of the ext4-patchqueue
> > > > > > http://repo.or.cz/w/ext4-patch-queue.git
> > > > >
> > > > > Thanks for the pointer but the page allocation failures that I hit seem
> > > > > to be caused by the memory management itself and the ext4 issue fixed by:
> > > > >
> > > > > http://repo.or.cz/w/ext4-patch-queue.git?a=blob;f=memory-leak-fix-ext4_group_info-allocation;h=c919fff34e70ec85f96d1833f9ce460c451000de;hb=HEAD
> > > > >
> > > > > is a different problem (unrelated to this one).
> > > >
> > > > Here is another data point.
> > > >
> > > > This time it is an order-6 page allocation failure for rt2870sta
> > > > (w/ upcoming driver changes) and Linus' tree from few days ago..
> > > >
> > >
> > > It's another high-order atomic allocation which is difficult to grant.
> > > I didn't look closely, but is this the same type of thing - large allocation
> > > failure during firmware loading? If so, is this during resume or is the
> > > device being reloaded for some other reason?
> >
> > Just modprobing the driver on a system running for some time.
> >
>
> Was this a common situation before?
Yes, just like firmware restarts with ipw2200.
> > > I suspect that there are going to be a few of these bugs cropping up
> > > every so often where network devices are assuming large atomic
> > > allocations will succeed because the "only time they happen" is during
> > > boot but these days are happening at runtime for other reasons.
> >
> > I wouldn't go so far as calling a normal order-6 (256kB) allocation on
> > 512MB machine with 1024MB swap a bug. Moreover such failures just never
> > happened before 2.6.31-rc1.
>
> It's not that normal, it's an allocation that cannot sleep and cannot
> reclaim. Why is something like firmware loading allocating memory like
OK.
> that? Is this use of GFP_ATOMIC relatively recent or has it always been
> that way?
It has always been like that.
> > I don't know why people don't see it but for me it has a memory management
> > regression and reliability issue written all over it.
> >
>
> Possibly but drivers that reload their firmware as a response to an
> error condition is relatively new and loading network drivers while the
> system is already up and running a long time does not strike me as
> typical system behaviour.
Loading drivers after boot is a typical desktop/laptop behavior, please
think about hotplug (the hardware in question is an USB dongle).
On Wed, Sep 2, 2009 at 10:48 AM, Bartlomiej
Zolnierkiewicz<[email protected]> wrote:
> On Sunday 30 August 2009 14:37:42 Bartlomiej Zolnierkiewicz wrote:
>> On Friday 28 August 2009 05:42:31 Zhu Yi wrote:
>> > Bartlomiej Zolnierkiewicz reported an atomic order-6 allocation failure
>> > for ipw2200 firmware loading in kernel 2.6.30. High order allocation is
>>
>> s/2.6.30/2.6.31-rc6/
>>
>> The issue has always been there but it was some recent change that
>> explicitly triggered the allocation failures (after 2.6.31-rc1).
>
> ipw2200 fix works fine but yesterday I got the following error while mounting
> ext4 filesystem (mb_history is optional so the mount succeeded):
OK so the mount succeeded.
> EXT4-fs (dm-2): barriers enabled
> kjournald2 starting: pid 3137, dev dm-2:8, commit interval 5 seconds
> EXT4-fs (dm-2): internal journal on dm-2:8
> EXT4-fs (dm-2): delayed allocation enabled
> EXT4-fs: file extents enabled
> mount: page allocation failure. order:5, mode:0xc0d0
> Pid: 3136, comm: mount Not tainted 2.6.31-rc8-00015-gadda766-dirty #78
> Call Trace:
> [<c0394de3>] ? printk+0xf/0x14
> [<c016a693>] __alloc_pages_nodemask+0x400/0x442
> [<c016a71b>] __get_free_pages+0xf/0x32
> [<c01865cf>] __kmalloc+0x28/0xfa
> [<c023d96f>] ? __spin_lock_init+0x28/0x4d
> [<c01f529d>] ext4_mb_init+0x392/0x460
> [<c01e99d2>] ext4_fill_super+0x1b96/0x2012
> [<c0239bc8>] ? snprintf+0x15/0x17
> [<c01c0b26>] ? disk_name+0x24/0x69
> [<c018ba63>] get_sb_bdev+0xda/0x117
> [<c01e6711>] ext4_get_sb+0x13/0x15
> [<c01e7e3c>] ? ext4_fill_super+0x0/0x2012
> [<c018ad2d>] vfs_kern_mount+0x3b/0x76
> [<c018adad>] do_kern_mount+0x33/0xbd
> [<c019d0af>] do_mount+0x660/0x6b8
> [<c016a71b>] ? __get_free_pages+0xf/0x32
> [<c019d168>] sys_mount+0x61/0x99
> [<c0102908>] sysenter_do_call+0x12/0x36
> Mem-Info:
> DMA per-cpu:
> CPU 0: hi: 0, btch: 1 usd: 0
> Normal per-cpu:
> CPU 0: hi: 186, btch: 31 usd: 0
> Active_anon:25471 active_file:22802 inactive_anon:25812
> inactive_file:33619 unevictable:2 dirty:2452 writeback:135 unstable:0
> free:4346 slab:4308 mapped:26038 pagetables:912 bounce:0
> DMA free:2060kB min:84kB low:104kB high:124kB active_anon:1660kB inactive_anon:1848kB active_file:144kB inactive_file:868kB unevictable:0kB present:15788kB pages_scanned:0 all_unreclaimable? no
> lowmem_reserve[]: 0 489 489
> Normal free:15324kB min:2788kB low:3484kB high:4180kB active_anon:100224kB inactive_anon:101400kB active_file:91064kB inactive_file:133608kB unevictable:8kB present:501392kB pages_scanned:0 all_unreclaimable? no
> lowmem_reserve[]: 0 0 0
> DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 2060kB
> Normal: 1283*4kB 648*8kB 159*16kB 53*32kB 10*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 15324kB
> 57947 total pagecache pages
> 878 pages in swap cache
> Swap cache stats: add 920, delete 42, find 11/11
> Free swap = 1016436kB
> Total swap = 1020116kB
> 131056 pages RAM
> 4233 pages reserved
> 90573 pages shared
> 77286 pages non-shared
> EXT4-fs: mballoc enabled
> EXT4-fs (dm-2): mounted filesystem with ordered data mode
>
> Thus it seems like the original bug is still there and any ideas how to
> debug the problem further are appreciated..
>
> The complete dmesg and kernel config are here:
>
> http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.dmesg
> http://www.kernel.org/pub/linux/kernel/people/bart/ext4-paf.config
This looks very similar to the kmemleak ext4 reports upon a mount. If
it is the same issue, which from the trace it seems it is, then this
is due to an extra kmalloc() allocation and this apparently will not
get fixed on 2.6.31 due to the closeness of the merge window and the
non-criticalness this issue has been deemed.
A patch fix is part of the ext4-patchqueue
http://repo.or.cz/w/ext4-patch-queue.git
Luis
On Monday 21 September 2009 12:56:48 Pekka Enberg wrote:
> On Mon, 2009-09-21 at 12:46 +0200, Bartlomiej Zolnierkiewicz wrote:
> > > > I don't know why people don't see it but for me it has a memory management
> > > > regression and reliability issue written all over it.
> > >
> > > Possibly but drivers that reload their firmware as a response to an
> > > error condition is relatively new and loading network drivers while the
> > > system is already up and running a long time does not strike me as
> > > typical system behaviour.
> >
> > Loading drivers after boot is a typical desktop/laptop behavior, please
> > think about hotplug (the hardware in question is an USB dongle).
>
> Yeah, I wonder what broke things. Did the wireless stack change in
> 2.6.31-rc1 too? IIRC Mel ruled out page allocator changes as a suspect.
The thing is that the mm behavior change has been narrowed down already
over a month ago to -mm merge in 2.6.31-rc1 (as has been noted in my initial
reports), I first though that that it was -next breakage but it turned out
that it came the other way around (because -mm is not even pulled into -next
currently -- great way to set an example for other kernel maintainers BTW).
I understand that behavior change may be justified and technically correct
in itself. I also completely agree that high order allocations in certain
drivers need fixing anyway.
However there is something wrong with the big picture and the way changes
are happening. I'm not saying that I'm surprised though, especially given
the recent decline in the quality assurance and the paradigm shift that
I'm seeing (some influential top level people talking that -rc1 is fine for
testing new code now or the "new kernel new hardware" thing).
Sorry but I have no more time currently to narrow down the issue some more
(guess what, there are other kernel bugs standing in the way to bisect it
and I would have to provide some reliable way to reproduce it first) so I
see no more point in wasting people's time on this. I can certainly get by
with allocation failure here and there. Not a big deal for me personally..