4.13 on thinkpad x220: oops when writing to SD card

Hi!

I tried to write to the MMC card; process hung and I got this in the dmesg.

[15909.353822] usb 2-1.2: Product: Ethernet Gadget
[15909.353826] usb 2-1.2: Manufacturer: Linux
4.12.0-03002-gec979a4-dirty with musb-hdrc
[15909.362182] cdc_ether 2-1.2:1.0 usb0: register 'cdc_ether' at
usb-0000:00:1d.0-1.2, CDC Ethernet Device, e2:f7:c0:44:db:77
[16109.316302] perf: interrupt took too long (2544 > 2500), lowering
kernel.perf_event_max_sample_rate to 78500
[18273.845406] mmc0: error -123 whilst initialising SD card
[18275.327982] mmc0: new high speed SDHC card at address 0003
[18275.328962] mmcblk0: mmc0:0003 SB08G 7.21 GiB
[18275.333698]  mmcblk0: p1 p2 p3
[18275.955293] EXT4-fs (mmcblk0p3): mounting ext3 file system using
the ext4 subsystem
[18276.013021] EXT4-fs (mmcblk0p3): recovery complete
[18276.016185] EXT4-fs (mmcblk0p3): mounted filesystem with ordered
data mode. Opts: (null)
[18306.524676]  mmcblk0: p1 p2 p3
[18439.780298] perf: interrupt took too long (3258 > 3180), lowering
kernel.perf_event_max_sample_rate to 61250
[19137.696497] perf: interrupt took too long (4082 > 4072), lowering
kernel.perf_event_max_sample_rate to 49000
[19925.945831] general protection fault: 0000 [#1] SMP
[19925.945909] Modules linked in:
[19925.945940] CPU: 2 PID: 30540 Comm: mmcqd/0 Not tainted 4.13.0 #123
[19925.946010] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW
(1.43 ) 10/12/2016
[19925.946168] task: ffff88001de9e800 task.stack: ffffc900087d4000
[19925.946293] RIP: 0010:blk_rq_map_sg+0x21a/0x4a3
[19925.946376] RSP: 0000:ffffc900087d7d10 EFLAGS: 00010202
[19925.946479] RAX: 6b6b6b6b6b6b6b68 RBX: 0000000000002000 RCX:
0000000000002000
[19925.946622] RDX: 6b6b6b6b6b6b6b6b RSI: 000000006eed2000 RDI:
ffff88009e32b9e0
[19925.946767] RBP: ffffc900087d7d68 R08: 0000000000000000 R09:
0000000063188000
[19925.946919] R10: 0000160000000000 R11: 6db6db6db6db6db7 R12:
0000000000000000
[19925.947059] R13: 0000000000001000 R14: 0000000000000002 R15:
ffffea00015ad5c0
[19925.947197] FS:  0000000000000000(0000) GS:ffff88019e280000(0000)
knlGS:0000000000000000
[19925.947347] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[19925.947454] CR2: 000000004482a000 CR3: 000000000521d000 CR4:
00000000000406a0
[19925.947586] Call Trace:
[19925.947634]  mmc_queue_map_sg+0x2f/0xa3
[19925.947703]  mmc_blk_rw_rq_prep+0x1fa/0x3d8
[19925.947777]  mmc_blk_issue_rw_rq+0xe8/0x419
[19925.947852]  mmc_blk_issue_rq+0x589/0x6e7
[19925.947924]  mmc_queue_thread+0xe1/0x175
[19925.947996]  kthread+0x13d/0x145
[19925.948050]  ? mmc_blk_issue_rq+0x6e7/0x6e7
[19925.948125]  ? kthread_bind+0x2c/0x2c
[19925.948191]  ? do_int80_syscall_32+0x5c/0xb4
[19925.948269]  ? SyS_exit_group+0xf/0xf
[19925.948337]  ret_from_fork+0x22/0x30
[19925.948394] Code: 89 e8 4a 8d 74 06 ff 48 09 f7 48 39 fa 75 05 89
48 0c eb 39 48 85 c0 74 0e 48 83 20 fd 48 89 c7 e8 83 02 02 00 eb 04
48 8b 45 b0 <48> 8b 10 83 e2 03 41 f6 c7 03 74 02 0f 0b 4c 09 fa 48 89
10 8b
[19925.948980] RIP: blk_rq_map_sg+0x21a/0x4a3 RSP: ffffc900087d7d10
[19925.958464] ---[ end trace 3ddfa379837fe00b ]---
pavel@duo:~$ uname -a
Linux duo 4.13.0 #123 SMP Mon Sep 4 10:42:23 CEST 2017 x86_64
GNU/Linux
pavel@duo:~$

Similar crash happened yesterday, but that time I got panic (blinking capslock) and stripes on screen. I did not use MMC before.

Any ideas?

Thanks,
Pavel

+ Seraphime

Quoted 4 lines · Pavel Machek

Hi!

I tried to write to the MMC card; process hung and I got this in the dmesg.

A similar report for 4.13 cycle was here:

https://lkml.org/lkml/2017/8/10/824

Seems 4.13-rc4 was already broken for that but unfortuantely I didn't reproduce that. So maybe Seraphime can do git-bisect as he said "I get it everytime" for which I assume it could be easy for him to find out the problematic commit?

Quoted 9 lines · Shawn Lin

+ Seraphime

Quoted 4 lines · Pavel Machek

Hi!

I tried to write to the MMC card; process hung and I got this in the dmesg.

Quoted 9 lines

A similar report for 4.13 cycle was here:

https://lkml.org/lkml/2017/8/10/824

Seems 4.13-rc4 was already broken for that but unfortuantely I didn't reproduce that. So maybe Seraphime can do git-bisect as he said "I get it everytime" for which I assume it could be easy for him to find out the problematic commit?

One obvious weakness in the new mmc_init_request() is the possibility that it might be called before card->bouncesz is set up. That could result in bouncing being done but mq_rq->bounce_sg is null. This might help:

drivers/mmc/core/queue.c +2 -0

index affa7370ba82..ad3e53e63abb 100644
@@ -242,6 +242,8 @@ int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card,
        if (mmc_dev(host)->dma_mask && *mmc_dev(host)->dma_mask)
                limit = (u64)dma_max_pfn(mmc_dev(host)) << PAGE_SHIFT;
 
+       card->bouncesz = mmc_queue_calc_bouncesz(host);
+
        mq->card = card;
        mq->queue = blk_alloc_queue(GFP_KERNEL);
        if (!mq->queue)

Another unrelated issue with mmc_init_request() is that mmc_exit_request() is not called if mmc_init_request() fails, which means mmc_init_request() must free anything it allocates when it fails.

+ Linus

Quoted 43 lines · Adrian Hunter

Quoted 9 lines · Shawn Lin

+ Seraphime

Quoted 4 lines · Pavel Machek

Hi!

I tried to write to the MMC card; process hung and I got this in the dmesg.

Quoted 9 lines

A similar report for 4.13 cycle was here:

https://lkml.org/lkml/2017/8/10/824

Seems 4.13-rc4 was already broken for that but unfortuantely I didn't reproduce that. So maybe Seraphime can do git-bisect as he said "I get it everytime" for which I assume it could be easy for him to find out the problematic commit?

One obvious weakness in the new mmc_init_request() is the possibility that it might be called before card->bouncesz is set up. That could result in bouncing being done but mq_rq->bounce_sg is null. This might help:

drivers/mmc/core/queue.c +2 -0

index affa7370ba82..ad3e53e63abb 100644
@@ -242,6 +242,8 @@ int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card,
        if (mmc_dev(host)->dma_mask && *mmc_dev(host)->dma_mask)
                limit = (u64)dma_max_pfn(mmc_dev(host)) << PAGE_SHIFT;
 
+       card->bouncesz = mmc_queue_calc_bouncesz(host);
+
        mq->card = card;
        mq->queue = blk_alloc_queue(GFP_KERNEL);
        if (!mq->queue)

@@ -265,7 +267,6 @@ int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card,
        if (mmc_can_erase(card))
                mmc_queue_setup_discard(mq->queue, card);
 

drivers/mmc/core/queue.c int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card, · line 272

Quoted 5 lines

drivers/mmc/core/queue.c +0 -1

-       card->bouncesz = mmc_queue_calc_bouncesz(host);
        if (card->bouncesz) {
                blk_queue_max_hw_sectors(mq->queue, card->bouncesz / 512);
                blk_queue_max_segments(mq->queue, card->bouncesz / 512);

Even if this fixes the problem it seems like we are papering over the real issue, which earlier fixes also did during the release cycle for v4.13.

Anyway I am happy to apply this as fix for 4.14, if Seraphime/Pavel can report it solved the problem. Could you send a proper patch with some changlog please?

I would also appreciate if can add you a small comment in the code, why moving this line is needed.

blk_init_allocated_queue() allocates 1 request for flush and 4 requests
for a memory pool. The memory pool requests only get used under memory pressure. That is why the error doesn't come up straight away.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

From: Adrian Hunter <[email protected]>
Date: Thu, 7 Sep 2017 10:40:35 +0300
Subject: [PATCH] mmc: block: Fix incorrectly initialized requests

mmc_init_request() depends on card->bouncesz so it must be calculated before blk_init_allocated_queue() starts allocating requests.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

---
 drivers/mmc/core/queue.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

drivers/mmc/core/queue.c +6 -2

index affa7370ba82..74c663b1c0a7 100644
@@ -242,6 +242,12 @@ int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card,
        if (mmc_dev(host)->dma_mask && *mmc_dev(host)->dma_mask)
                limit = (u64)dma_max_pfn(mmc_dev(host)) << PAGE_SHIFT;
 
+       /*
+        * mmc_init_request() depends on card->bouncesz so it must be calculated
+        * before blk_init_allocated_queue() starts allocating requests.
+        */
+       card->bouncesz = mmc_queue_calc_bouncesz(host);
+
        mq->card = card;
        mq->queue = blk_alloc_queue(GFP_KERNEL);
        if (!mq->queue)

@@ -265,7 +271,6 @@ int mmc_init_queue(struct mmc_queue *mq, struct mmc_card *card,
        if (mmc_can_erase(card))
                mmc_queue_setup_discard(mq->queue, card);
 
-       card->bouncesz = mmc_queue_calc_bouncesz(host);
        if (card->bouncesz) {
                blk_queue_max_hw_sectors(mq->queue, card->bouncesz / 512);
                blk_queue_max_segments(mq->queue, card->bouncesz / 512);
--

1.9.1

[...]

Quoted 5 lines

From: Adrian Hunter <[email protected]>
Date: Thu, 7 Sep 2017 10:40:35 +0300
Subject: [PATCH] mmc: block: Fix incorrectly initialized requests

Quoted 6 lines

mmc_init_request() depends on card->bouncesz so it must be calculated before blk_init_allocated_queue() starts allocating requests.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

Thanks, applied for fixes!

Quoted 14 lines · Ulf Hansson

[...]

Quoted 11 lines

From: Adrian Hunter <[email protected]>
Date: Thu, 7 Sep 2017 10:40:35 +0300
Subject: [PATCH] mmc: block: Fix incorrectly initialized requests

mmc_init_request() depends on card->bouncesz so it must be calculated before blk_init_allocated_queue() starts allocating requests.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

Quoted 1 line

Thanks, applied for fixes!

Thanks. I believe this one should get cc: stable markups, so eventually 4.13 does get fixed, too....
Pavel

[...]

Quoted 5 lines

From: Adrian Hunter <[email protected]>
Date: Thu, 7 Sep 2017 10:40:35 +0300
Subject: [PATCH] mmc: block: Fix incorrectly initialized requests

Quoted 6 lines

mmc_init_request() depends on card->bouncesz so it must be calculated before blk_init_allocated_queue() starts allocating requests.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

Thanks, applied for fixes!

From: Adrian Hunter <[email protected]>
Date: Thu, 7 Sep 2017 10:40:35 +0300
Subject: [PATCH] mmc: block: Fix incorrectly initialized requests

mmc_init_request() depends on card->bouncesz so it must be calculated before blk_init_allocated_queue() starts allocating requests.

Reported-by Seraphime Kirkovski <[email protected]>

Fixes 304419d8a7e92 ("mmc: core: Allocate per-request data using the block layer core")

Signed-off-by Adrian Hunter <[email protected]>

Even if this fixes the problem it seems like we are papering over the real issue, which earlier fixes also did during the release cycle for v4.13.

Quoted 3 lines

Another unrelated issue with mmc_init_request() is that mmc_exit_request() is not called if mmc_init_request() fails, which means mmc_init_request() must free anything it allocates when it fails.

Yes, the situations it's just too fragile. We need to fix the behavior properly, although I haven't myself been able to investigate exactly how yet.

Adding, Linus, perhaps he has some ideas.

Quoted 3 lines · Ulf Hansson

Even if this fixes the problem it seems like we are papering over the real issue, which earlier fixes also did during the release cycle for v4.13.

I think this is the real solution to the issue.

Quoted 8 lines

Quoted 3 lines

Another unrelated issue with mmc_init_request() is that mmc_exit_request() is not called if mmc_init_request() fails, which means mmc_init_request() must free anything it allocates when it fails.

Yes, the situations it's just too fragile. We need to fix the behavior properly, although I haven't myself been able to investigate exactly how yet.

Quoted 1 line

Adding, Linus, perhaps he has some ideas.

Maybe we should simply bite the bullet and do what was suggested by another contributor when I refactored the bounce buffer handling:
simply delete the bounce buffer code and let any remaining (few?) legacy devices suffer a bit (performancewise) at the gain of way simpler code?

I am a bit hesitant about that because Pierre Ossman said it was actually a big win on the SDHC hosts that made use of it at one point.

Yours,
Linus Walleij

Quoted 21 lines · Linus Walleij

Quoted 3 lines · Ulf Hansson

Even if this fixes the problem it seems like we are papering over the real issue, which earlier fixes also did during the release cycle for v4.13.

I think this is the real solution to the issue.

Quoted 11 lines

Quoted 5 lines

Another unrelated issue with mmc_init_request() is that mmc_exit_request()
is not called if mmc_init_request() fails, which means mmc_init_request()
must free anything it allocates when it fails.

Yes, the situations it's just too fragile. We need to fix the behavior properly, although I haven't myself been able to investigate exactly how yet.

Quoted 8 lines

Quoted 1 line

Adding, Linus, perhaps he has some ideas.

Maybe we should simply bite the bullet and do what was suggested by another contributor when I refactored the bounce buffer handling:
simply delete the bounce buffer code and let any remaining (few?) legacy devices suffer a bit (performancewise) at the gain of way simpler code?

Are you in the same page with what Adrian pointed to?

IIUC, the issue is:
init_rq_fn will be called each time when trying to create new reuqest from the pre-allocated request_list memeory pool, and exit_rq_fn will is in the corresponding routine to free request from request_list (blk_free_request) when finished. But if alloc_request_size fails, it won't call exit_rq_fn, so you need to prevent memory leak on your own error path of init_rq_fn.

But you seem to talk about removing the bounce buffer and so finally get rid of registering init_rq_fn/exit_rq_fn?

That is another thing,
and what we right now need to do is to fix the pontential memory leak. It's quite a simple action, right? :)

Quoted 3 lines

I am a bit hesitant about that because Pierre Ossman said it was actually a big win on the SDHC hosts that made use of it at one point.

You had removed packed cmd support to simplify the code, so I think this is another trade-off need to ask: What you want? and keep consistent with the direction you insisted on.

Quoted 33 lines · Shawn Lin

Quoted 21 lines · Linus Walleij

Quoted 3 lines · Ulf Hansson

Even if this fixes the problem it seems like we are papering over the real issue, which earlier fixes also did during the release cycle for v4.13.

I think this is the real solution to the issue.

Quoted 11 lines

Quoted 5 lines

Another unrelated issue with mmc_init_request() is that mmc_exit_request()
is not called if mmc_init_request() fails, which means mmc_init_request()
must free anything it allocates when it fails.

Yes, the situations it's just too fragile. We need to fix the behavior properly, although I haven't myself been able to investigate exactly how yet.

Quoted 8 lines

Quoted 1 line

Adding, Linus, perhaps he has some ideas.

Maybe we should simply bite the bullet and do what was suggested by another contributor when I refactored the bounce buffer handling:
simply delete the bounce buffer code and let any remaining (few?) legacy devices suffer a bit (performancewise) at the gain of way simpler code?

Are you in the same page with what Adrian pointed to?

Quoted 7 lines

IIUC, the issue is:
init_rq_fn will be called each time when trying to create new reuqest from the pre-allocated request_list memeory pool, and exit_rq_fn will is in the corresponding routine to free request from request_list (blk_free_request) when finished. But if alloc_request_size fails, it won't call exit_rq_fn, so you need to prevent memory leak on your own error path of init_rq_fn.

Yes and that is what the current patch fixes, is it not?

Quoted 3 lines

But you seem to talk about removing the bounce buffer and so finally get rid of registering init_rq_fn/exit_rq_fn?

That is in direct response to Ulf's statement
"the situations it's just too fragile" and what can be done about that is not make the code even more complex but make it simpler and easier to follow.

One way to achieve that in the long term, is to delete bounce buffer handling since it adds overhead and complexity.

Quoted 3 lines

That is another thing,
and what we right now need to do is to fix the pontential memory leak. It's quite a simple action, right? :)

It is another thing.

This patch fixes a memory leak, but Ulf is asking how we may avoid fragile behaviour.

Quoted 4 lines

Quoted 3 lines

I am a bit hesitant about that because Pierre Ossman said it was actually a big win on the SDHC hosts that made use of it at one point.

Quoted 3 lines

You had removed packed cmd support to simplify the code, so I think this is another trade-off need to ask: What you want? and keep consistent with the direction you insisted on.

Packed command could be removed because it was not used by any in-tree code. See
commit 03d640ae1f9b24b1d2a11f747143a1ecc0745019

Bounce buffers on the other hand, as this patch shows, is very much in use. So if they e.g. improve throughput on these systems (mainly laptops I think?) it should definately be kept around.

It might be a good idea to make a patch to remove the bounce buffers and ask people to do before/after throughput tests, because I do not have this hardware myself. If it doesn't provide any throughput improvements to any system in use, it should be deleted. But I don't know that yet.

Yours,
Linus Walleij

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

[10994.299846] mmc0: new high speed SDHC card at address 0003
[10994.302196] kworker/2:1: page allocation failure: order:4,
mode:0x16040c0(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)
[10994.302212] CPU: 2 PID: 9500 Comm: kworker/2:1 Not tainted
4.14.0-rc2 #135
[10994.302215] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW
(1.43 ) 10/12/2016
[10994.302222] Workqueue: events_freezable mmc_rescan
[10994.302227] Call Trace:
[10994.302233]  dump_stack+0x4d/0x67
[10994.302239]  warn_alloc+0xde/0x180
[10994.302243]  __alloc_pages_nodemask+0xaa4/0xd30
[10994.302249]  ? cache_alloc_refill+0xb73/0xc10
[10994.302252]  cache_alloc_refill+0x101/0xc10
[10994.302258]  ? mmc_init_request+0x2d/0xd0
[10994.302262]  ? mmc_init_request+0x2d/0xd0
[10994.302265]  __kmalloc+0xaf/0xe0
[10994.302269]  mmc_init_request+0x2d/0xd0
[10994.302273]  alloc_request_size+0x45/0x60
[10994.302276]  ? free_request_size+0x30/0x30
[10994.302280]  mempool_create_node+0xd7/0x130
[10994.302283]  ? alloc_request_simple+0x20/0x20
[10994.302287]  blk_init_rl+0xe8/0x110
[10994.302290]  blk_init_allocated_queue+0x70/0x180
[10994.302294]  mmc_init_queue+0xdd/0x370
[10994.302297]  mmc_blk_alloc_req+0xf6/0x340
[10994.302301]  mmc_blk_probe+0x18b/0x4e0
[10994.302305]  mmc_bus_probe+0x12/0x20
[10994.302309]  driver_probe_device+0x2f4/0x490

Order 4 allocations are not supposed to be reliable...

Any ideas?

Thanks,
Pavel

Hi!

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Quoted 31 lines

[10994.299846] mmc0: new high speed SDHC card at address 0003
[10994.302196] kworker/2:1: page allocation failure: order:4,
mode:0x16040c0(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)
[10994.302212] CPU: 2 PID: 9500 Comm: kworker/2:1 Not tainted
4.14.0-rc2 #135
[10994.302215] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW
(1.43 ) 10/12/2016
[10994.302222] Workqueue: events_freezable mmc_rescan
[10994.302227] Call Trace:
[10994.302233]  dump_stack+0x4d/0x67
[10994.302239]  warn_alloc+0xde/0x180
[10994.302243]  __alloc_pages_nodemask+0xaa4/0xd30
[10994.302249]  ? cache_alloc_refill+0xb73/0xc10
[10994.302252]  cache_alloc_refill+0x101/0xc10
[10994.302258]  ? mmc_init_request+0x2d/0xd0
[10994.302262]  ? mmc_init_request+0x2d/0xd0
[10994.302265]  __kmalloc+0xaf/0xe0
[10994.302269]  mmc_init_request+0x2d/0xd0
[10994.302273]  alloc_request_size+0x45/0x60
[10994.302276]  ? free_request_size+0x30/0x30
[10994.302280]  mempool_create_node+0xd7/0x130
[10994.302283]  ? alloc_request_simple+0x20/0x20
[10994.302287]  blk_init_rl+0xe8/0x110
[10994.302290]  blk_init_allocated_queue+0x70/0x180
[10994.302294]  mmc_init_queue+0xdd/0x370
[10994.302297]  mmc_blk_alloc_req+0xf6/0x340
[10994.302301]  mmc_blk_probe+0x18b/0x4e0
[10994.302305]  mmc_bus_probe+0x12/0x20
[10994.302309]  driver_probe_device+0x2f4/0x490

Quoted 7 lines

Order 4 allocations are not supposed to be reliable...

Any ideas?

Thanks,
Pavel

Signature · 2 lines

(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Quoted 9 lines · Pavel Machek

Hi!

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Yes, 16 pages is costly allocations which will fail without invoking the OOM killer. But I thought this is an interesting case, for mempool allocation should be able to handle memory allocation failure except initial allocations, and initial allocation is failing.

I think that using kvmalloc() (and converting corresponding kfree() to kvfree()) will make initial allocations succeed, but that might cause needlessly succeeding subsequent mempool allocations under memory pressure?

Quoted 44 lines

Quoted 38 lines

[10994.299846] mmc0: new high speed SDHC card at address 0003
[10994.302196] kworker/2:1: page allocation failure: order:4,
mode:0x16040c0(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)
[10994.302212] CPU: 2 PID: 9500 Comm: kworker/2:1 Not tainted
4.14.0-rc2 #135
[10994.302215] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW
(1.43 ) 10/12/2016
[10994.302222] Workqueue: events_freezable mmc_rescan
[10994.302227] Call Trace:
[10994.302233]  dump_stack+0x4d/0x67
[10994.302239]  warn_alloc+0xde/0x180
[10994.302243]  __alloc_pages_nodemask+0xaa4/0xd30
[10994.302249]  ? cache_alloc_refill+0xb73/0xc10
[10994.302252]  cache_alloc_refill+0x101/0xc10
[10994.302258]  ? mmc_init_request+0x2d/0xd0
[10994.302262]  ? mmc_init_request+0x2d/0xd0
[10994.302265]  __kmalloc+0xaf/0xe0
[10994.302269]  mmc_init_request+0x2d/0xd0
[10994.302273]  alloc_request_size+0x45/0x60
[10994.302276]  ? free_request_size+0x30/0x30
[10994.302280]  mempool_create_node+0xd7/0x130
[10994.302283]  ? alloc_request_simple+0x20/0x20
[10994.302287]  blk_init_rl+0xe8/0x110
[10994.302290]  blk_init_allocated_queue+0x70/0x180
[10994.302294]  mmc_init_queue+0xdd/0x370
[10994.302297]  mmc_blk_alloc_req+0xf6/0x340
[10994.302301]  mmc_blk_probe+0x18b/0x4e0
[10994.302305]  mmc_bus_probe+0x12/0x20
[10994.302309]  driver_probe_device+0x2f4/0x490

Order 4 allocations are not supposed to be reliable...

Any ideas?

Thanks,
Pavel

Signature · 2 lines

(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

The memory allocation used to be optional but became mandatory with:

commit 304419d8a7e9204c5d19b704467b814df8c8f5b1
Author: Linus Walleij <[email protected]>
Date: Thu May 18 11:29:32 2017 +0200

mmc: core: Allocate per-request data using the block layer core

There is also a bug in mmc_init_request() where it doesn't free it's allocations on the error path, so you might want to check if you are leaking memory.

Bounce buffers are being removed from v4.15 although you may experience performance regression with that:

	https://marc.info/?l=linux-mmc&m=150589778700551

Quoted 65 lines

Quoted 9 lines · Pavel Machek

Hi!

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Yes, 16 pages is costly allocations which will fail without invoking the OOM killer. But I thought this is an interesting case, for mempool allocation should be able to handle memory allocation failure except initial allocations, and initial allocation is failing.

I think that using kvmalloc() (and converting corresponding kfree() to kvfree()) will make initial allocations succeed, but that might cause needlessly succeeding subsequent mempool allocations under memory pressure?

Quoted 44 lines

Quoted 38 lines

[10994.299846] mmc0: new high speed SDHC card at address 0003
[10994.302196] kworker/2:1: page allocation failure: order:4,
mode:0x16040c0(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK), nodemask=(null)
[10994.302212] CPU: 2 PID: 9500 Comm: kworker/2:1 Not tainted
4.14.0-rc2 #135
[10994.302215] Hardware name: LENOVO 42872WU/42872WU, BIOS 8DET73WW
(1.43 ) 10/12/2016
[10994.302222] Workqueue: events_freezable mmc_rescan
[10994.302227] Call Trace:
[10994.302233]  dump_stack+0x4d/0x67
[10994.302239]  warn_alloc+0xde/0x180
[10994.302243]  __alloc_pages_nodemask+0xaa4/0xd30
[10994.302249]  ? cache_alloc_refill+0xb73/0xc10
[10994.302252]  cache_alloc_refill+0x101/0xc10
[10994.302258]  ? mmc_init_request+0x2d/0xd0
[10994.302262]  ? mmc_init_request+0x2d/0xd0
[10994.302265]  __kmalloc+0xaf/0xe0
[10994.302269]  mmc_init_request+0x2d/0xd0
[10994.302273]  alloc_request_size+0x45/0x60
[10994.302276]  ? free_request_size+0x30/0x30
[10994.302280]  mempool_create_node+0xd7/0x130
[10994.302283]  ? alloc_request_simple+0x20/0x20
[10994.302287]  blk_init_rl+0xe8/0x110
[10994.302290]  blk_init_allocated_queue+0x70/0x180
[10994.302294]  mmc_init_queue+0xdd/0x370
[10994.302297]  mmc_blk_alloc_req+0xf6/0x340
[10994.302301]  mmc_blk_probe+0x18b/0x4e0
[10994.302305]  mmc_bus_probe+0x12/0x20
[10994.302309]  driver_probe_device+0x2f4/0x490

Order 4 allocations are not supposed to be reliable...

Any ideas?

Thanks,
Pavel

Signature · 2 lines

(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Quoted 1 line

Bounce buffers are being removed from v4.15

although you may experience

Quoted 3 lines

performance regression with that:

      https://marc.info/?l=linux-mmc&m=150589778700551

Hmm. The performance of this is already pretty bad, I really hope it does not get any worse.

Quoted 1 line · Pavel Machek

Quoted 1 line

Bounce buffers are being removed from v4.15

As Adrian states, this would make any last bugs go away. I would even consider putting this patch this into fixes if it solves the problem.

Quoted 3 lines

although you may experience

Quoted 2 lines

performance regression with that:

Quoted 4 lines

Quoted 1 line

      https://marc.info/?l=linux-mmc&m=150589778700551

Hmm. The performance of this is already pretty bad, I really hope it does not get any worse.

Did you use bounce buffers? Those were improving performance on some laptops with TI or Ricoh host controllers and nothing else was ever really using it (as can be seen from the commit).

Quoted 15 lines · Linus Walleij

Quoted 1 line · Pavel Machek

Quoted 1 line

Bounce buffers are being removed from v4.15

As Adrian states, this would make any last bugs go away. I would even consider putting this patch this into fixes if it solves the problem.

Quoted 7 lines

although you may experience

Quoted 3 lines

performance regression with that:

      https://marc.info/?l=linux-mmc&m=150589778700551

Hmm. The performance of this is already pretty bad, I really hope it does not get any worse.

Quoted 3 lines

Did you use bounce buffers? Those were improving performance on some laptops with TI or Ricoh host controllers and nothing else was ever really using it (as can be seen from the commit).

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

Quoted 6 lines

Quoted 3 lines

Did you use bounce buffers? Those were improving performance on some laptops with TI or Ricoh host controllers and nothing else was ever really using it (as can be seen from the commit).

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Quoted 4 lines

Quoted 2 lines

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Here is the output:
0d:00.0 System peripheral [0880]: Ricoh Co Ltd PCIe SDXC/MMC Host Controller [1180:e823] (rev 07)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: sdhci-pci

[10994.302196] kworker/2:1: page allocation failure: order:4,

Quoted 9 lines · Pavel Machek

Quoted 4 lines

Quoted 2 lines

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Here is the output:
0d:00.0 System peripheral [0880]: Ricoh Co Ltd PCIe SDXC/MMC Host Controller [1180:e823] (rev 07)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: sdhci-pci

So that is a Ricoh driver, one of the few that was supposed to benefit from bounce buffers.

Except that if you actually turned it on:

Quoted 1 line

[10994.302196] kworker/2:1: page allocation failure: order:4,

so it doesn't have enough memory to use these bounce buffers anyway.

I'm now feel it was the right thing to delete them.

Quoted 12 lines · Linus Walleij

Quoted 9 lines · Pavel Machek

Quoted 4 lines

Quoted 2 lines

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Here is the output:
0d:00.0 System peripheral [0880]: Ricoh Co Ltd PCIe SDXC/MMC Host Controller [1180:e823] (rev 07)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: sdhci-pci

Quoted 7 lines

So that is a Ricoh driver, one of the few that was supposed to benefit from bounce buffers.

Except that if you actually turned it on:

Quoted 1 line

[10994.302196] kworker/2:1: page allocation failure: order:4,

so it doesn't have enough memory to use these bounce buffers anyway.

Well, look at archives: driver failed completely when allocation failed.

Quoted 1 line

I'm now feel it was the right thing to delete them.

Which means I may have been geting benefit -- when it worked. I believe solution is to allocate at driver probing time.

(OTOH ... SPI is slow compared to rest of the system, right? Where does the benefit come from?)

Quoted 15 lines · Linus Walleij

Quoted 9 lines · Pavel Machek

Quoted 4 lines

Quoted 2 lines

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Here is the output:
0d:00.0 System peripheral [0880]: Ricoh Co Ltd PCIe SDXC/MMC Host Controller [1180:e823] (rev 07)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: sdhci-pci

So that is a Ricoh driver, one of the few that was supposed to benefit from bounce buffers.

Quoted 4 lines

Except that if you actually turned it on:

Quoted 1 line

[10994.302196] kworker/2:1: page allocation failure: order:4,

so it doesn't have enough memory to use these bounce buffers anyway.

Well, look at archives: driver failed completely when allocation failed.

Quoted 1 line

I'm now feel it was the right thing to delete them.

Which means I may have been geting benefit -- when it worked. I believe solution is to allocate at driver probing time.

(OTOH ... SPI is slow compared to rest of the system, right? Where does the benefit come from?)

Hi!

Quoted 8 lines

Quoted 6 lines

Quoted 3 lines

Did you use bounce buffers? Those were improving performance on some laptops with TI or Ricoh host controllers and nothing else was ever really using it (as can be seen from the commit).

Thinkpad X220... how do I tell if I was using them? I believe so, because I uncovered bug in them before.

You are certainly using bounce buffers. What does lspci -knn show?

Here is the output:
Pavel

00:00.0 Host bridge [0600]: Intel Corporation 2nd Generation Core Processor Family DRAM Controller [8086:0104] (rev 09)
Subsystem: Lenovo Device [17aa:21da]
00:02.0 VGA compatible controller [0300]: Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller [8086:0126] (rev 09)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: i915
00:16.0 Communication controller [0780]: Intel Corporation 6 Series/C200 Series Chipset Family MEI Controller #1 [8086:1c3a] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
00:19.0 Ethernet controller [0200]: Intel Corporation 82579LM Gigabit Network Connection [8086:1502] (rev 04)
Subsystem: Lenovo Device [17aa:21ce]
Kernel driver in use: e1000e
00:1a.0 USB controller [0c03]: Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #2 [8086:1c2d] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: ehci-pci
00:1b.0 Audio device [0403]: Intel Corporation 6 Series/C200 Series Chipset Family High Definition Audio Controller [8086:1c20] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: snd_hda_intel
00:1c.0 PCI bridge [0604]: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 1 [8086:1c10] (rev b4)
Kernel driver in use: pcieport
00:1c.1 PCI bridge [0604]: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 2 [8086:1c12] (rev b4)
Kernel driver in use: pcieport
00:1c.3 PCI bridge [0604]: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 4 [8086:1c16] (rev b4)
Kernel driver in use: pcieport
00:1c.4 PCI bridge [0604]: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 5 [8086:1c18] (rev b4)
Kernel driver in use: pcieport
00:1d.0 USB controller [0c03]: Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #1 [8086:1c26] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: ehci-pci
00:1f.0 ISA bridge [0601]: Intel Corporation QM67 Express Chipset Family LPC Controller [8086:1c4f] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
00:1f.2 SATA controller [0106]: Intel Corporation 6 Series/C200 Series Chipset Family 6 port SATA AHCI Controller [8086:1c03] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: ahci

00:1f.3 SMBus [0c05]: Intel Corporation 6 Series/C200 Series Chipset Family SMBus Controller [8086:1c22] (rev 04)
Subsystem: Lenovo Device [17aa:21da]
03:00.0 Network controller [0280]: Intel Corporation Centrino Wireless-N 1000 [Condor Peak] [8086:0084]
Subsystem: Intel Corporation Centrino Wireless-N 1000 BGN [8086:1315]
Kernel driver in use: iwlwifi
0d:00.0 System peripheral [0880]: Ricoh Co Ltd PCIe SDXC/MMC Host Controller [1180:e823] (rev 07)
Subsystem: Lenovo Device [17aa:21da]
Kernel driver in use: sdhci-pci

Quoted 7 lines

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Yes, 16 pages is costly allocations which will fail without invoking the OOM killer. But I thought this is an interesting case, for mempool allocation should be able to handle memory allocation failure except initial allocations, and initial allocation is failing.

I think that using kvmalloc() (and converting corresponding kfree() to kvfree()) will make initial allocations succeed, but that might cause needlessly succeeding subsequent mempool allocations under memory pressure?

Quoted 7 lines · Tetsuo Handa

Quoted 7 lines

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

I'm not sure I fully understand this error message:
"worker/2:1: page allocation failure: order:4"

What I guess from context is that the mmc_init_request() call is failing to allocate 16 pages, meaning for 4K pages 64KB which is the typical bounce buffer.

This is what the code has always allocated as bounce buffer, but it used to happen upfront, when probing the MMC block layer, rather than when allocating the requests.

Quoted 15 lines · Linus Walleij

Quoted 7 lines · Tetsuo Handa

Quoted 7 lines

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

I'm not sure I fully understand this error message:
"worker/2:1: page allocation failure: order:4"

Quoted 7 lines

What I guess from context is that the mmc_init_request() call is failing to allocate 16 pages, meaning for 4K pages 64KB which is the typical bounce buffer.

This is what the code has always allocated as bounce buffer, but it used to happen upfront, when probing the MMC block layer, rather than when allocating the requests.

That is not exactly right. As I already wrote, the memory allocation used to be optional but became mandatory with:

commit 304419d8a7e9204c5d19b704467b814df8c8f5b1
Author: Linus Walleij <[email protected]>
Date: Thu May 18 11:29:32 2017 +0200

mmc: core: Allocate per-request data using the block layer core

Quoted 24 lines · Adrian Hunter

Quoted 15 lines · Linus Walleij

Quoted 7 lines · Tetsuo Handa

Quoted 7 lines

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

I'm not sure I fully understand this error message:
"worker/2:1: page allocation failure: order:4"

Quoted 7 lines

What I guess from context is that the mmc_init_request() call is failing to allocate 16 pages, meaning for 4K pages 64KB which is the typical bounce buffer.

This is what the code has always allocated as bounce buffer, but it used to happen upfront, when probing the MMC block layer, rather than when allocating the requests.

Quoted 8 lines

That is not exactly right. As I already wrote, the memory allocation used to be optional but became mandatory with:

commit 304419d8a7e9204c5d19b704467b814df8c8f5b1
Author: Linus Walleij <[email protected]>
Date: Thu May 18 11:29:32 2017 +0200

mmc: core: Allocate per-request data using the block layer core

Yes you are right, it used to look like this, with the bounce buffer hiding behind a Kconfig symbol:

#ifdef CONFIG_MMC_BLOCK_BOUNCE
    if (host->max_segs == 1) {
        unsigned int bouncesz;

        bouncesz = MMC_QUEUE_BOUNCESZ;

        if (bouncesz > host->max_req_size)
            bouncesz = host->max_req_size;
        if (bouncesz > host->max_seg_size)
            bouncesz = host->max_seg_size;
        if (bouncesz > (host->max_blk_count * 512))
            bouncesz = host->max_blk_count * 512;

        if (bouncesz > 512 &&
            mmc_queue_alloc_bounce_bufs(mq, bouncesz)) {
            blk_queue_bounce_limit(mq->queue, BLK_BOUNCE_ANY);
            blk_queue_max_hw_sectors(mq->queue, bouncesz / 512);
            blk_queue_max_segments(mq->queue, bouncesz / 512);
            blk_queue_max_segment_size(mq->queue, bouncesz);

            ret = mmc_queue_alloc_bounce_sgs(mq, bouncesz);
            if (ret)
                goto cleanup_queue;
            bounce = true;
        }
    }

#endif

I recently concluded that I find no evidence whatsoever that anyone turned this symbol on. Actually. (Checked defconfigs and distro configs.) The option was just sitting there unused.
This code was never exercised except by some people who turned it on on their custom kernels in the past. It's in practice dead code.

My patch started to allocate and use bounce buffers for all hosts with max_segs == 1, unless specifically flagged NOT to use bounce buffers.

That wasn't smart, I should have just deleted them. Mea culpa.

So that is why I asked Ulf to simply put the patch deleting the bounce buffers that noone is using to fixes, and it should fix this problem.

Hi!

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Quoted 7 lines · Pavel Machek

Hi!

Quoted 2 lines

I inserted u-SD card, only to realize that it is not detected as it should be. And dmesg indeed reveals:

Tetsuo asked me to report this to linux-mm.

Quoted 2 lines

But 2^4 is 16 pages, IIRC that can't be expected to work reliably, and thus this sounds like MMC bug, not mm bug.

Well, I cannot comment on why MMC needs such a large allocation and whether it can safely fall back to vmalloc but __GFP_RETRY_MAYFAIL might help to try harder and require compaction to do more work. Relying on that for correctness is, of course, a different story and a very unreliable under memory pressure or long term fragmented memory.