Re: discard feature, mkfs.ext4 and mmc default fallback to normal erase op

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi Ulf, Ted,

Am 2020-12-08 17:17, schrieb Ulf Hansson:
On Tue, 8 Dec 2020 at 12:26, Michael Walle <michael@xxxxxxxx> wrote:
> To find performance bottlenecks, I would start looking at what actual
> eMMC/SD commands/args we end up mapping towards the
> REQ_OP_DISCARD/REQ_OP_SECURE_ERASE requests. Then definitely, I would
> also look at the values we end up picking as max discard sectors and
> the discard granularity.

I'm just about finding some SD cards and looking how they behave timing
wise and what they report they support (ie. erase or discard). Looks
like other cards are doing better. But I'd have to find out if they
support the discard (mine doesn't) and if they are slow too if I force
them to use the normal erase.

Sounds great, looking forward to hear more about your findings.

Ok so sample size is 3 *g*. Two of these cards are actually "fast",
meaning that a discard of any size will take less than a second and
one is the slow card.

I've added tracing to dump the cards parameters (see patch at the end
of this mail). No card supports discard, they just use the normal erase
method. That wasn't what I was expecting ;)

(1) Fast card (Kingston CANVAS Select Plus, 16GB)
# time blkdiscard -l 536870912 /dev/mmcblk1
real	0m 0.34s
user	0m 0.00s
sys	0m 0.00s

kworker/0:2-81 [000] .... 123.285801: mmc_sd_setup_card: card->erase_arg=0, au=9 es=512 et=12 eo=3 kworker/1:3H-2368 [001] .... 133.570762: mmc_do_erase: from=0x0 to=0x1fff kworker/1:3H-2368 [001] .... 133.585204: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.585284: mmc_do_erase: from=0x2000 to=0x3fff kworker/1:3H-2368 [001] .... 133.589201: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.589217: mmc_do_erase: from=0x4000 to=0x5fff kworker/1:3H-2368 [001] .... 133.591315: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.591330: mmc_do_erase: from=0x6000 to=0x7fff kworker/1:3H-2368 [001] .... 133.593202: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.593217: mmc_do_erase: from=0x8000 to=0x9fff kworker/1:3H-2368 [001] .... 133.595338: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.595353: mmc_do_erase: from=0xa000 to=0xbfff kworker/1:3H-2368 [001] .... 133.597473: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.597488: mmc_do_erase: from=0xc000 to=0xdfff kworker/1:3H-2368 [001] .... 133.599605: mmc_do_erase: mmc_poll_for_busy() done
[..]
kworker/1:3H-2368 [001] .... 133.891681: mmc_do_erase: from=0xf0000 to=0xf1fff kworker/1:3H-2368 [001] .... 133.893919: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.893947: mmc_do_erase: from=0xf2000 to=0xf3fff kworker/1:3H-2368 [001] .... 133.896186: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.896213: mmc_do_erase: from=0xf4000 to=0xf5fff kworker/1:3H-2368 [001] .... 133.898452: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.898481: mmc_do_erase: from=0xf6000 to=0xf7fff kworker/1:3H-2368 [001] .... 133.900713: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.900741: mmc_do_erase: from=0xf8000 to=0xf9fff kworker/1:3H-2368 [001] .... 133.902979: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.903008: mmc_do_erase: from=0xfa000 to=0xfbfff kworker/1:3H-2368 [001] .... 133.905246: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.905274: mmc_do_erase: from=0xfc000 to=0xfdfff kworker/1:3H-2368 [001] .... 133.909589: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 133.909620: mmc_do_erase: from=0xfe000 to=0xfffff kworker/1:3H-2368 [001] .... 133.911870: mmc_do_erase: mmc_poll_for_busy() done


(2) Fast card (Panasonic, Unknown model, 8GB)
kworker/0:2-81 [000] .... 492.192453: mmc_sd_setup_card: card->erase_arg=0, au=9 es=8 et=1 eo=3

    I didn't discard the blocks again, so no logs, but it didn't take
    long in the first run.


(3) Slow card (Toshiba Exceria, 16GB)
# time blkdiscard -l 536870912 /dev/mmcblk1
real	0m 39.78s
user	0m 0.00s
sys	0m 0.00s

kworker/0:2-81 [000] .... 207.271171: mmc_sd_setup_card: card->erase_arg=0, au=9 es=512 et=12 eo=3 kworker/1:3H-2368 [001] .... 212.096265: mmc_do_erase: from=0x0 to=0x1fff kworker/1:3H-2368 [001] .... 212.100282: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 212.100328: mmc_do_erase: from=0x2000 to=0x3fff kworker/1:3H-2368 [001] .... 212.102207: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 212.102215: mmc_do_erase: from=0x4000 to=0x5fff kworker/1:3H-2368 [001] .... 212.104260: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 212.104267: mmc_do_erase: from=0x6000 to=0x7fff kworker/1:3H-2368 [001] .... 213.086808: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.086842: mmc_do_erase: from=0x8000 to=0x9fff kworker/1:3H-2368 [001] .... 213.149232: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.149263: mmc_do_erase: from=0xa000 to=0xbfff kworker/1:3H-2368 [001] .... 213.215185: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.215216: mmc_do_erase: from=0xc000 to=0xdfff kworker/1:3H-2368 [001] .... 213.346672: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.346702: mmc_do_erase: from=0xe000 to=0xffff kworker/1:3H-2368 [001] .... 213.412594: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.412623: mmc_do_erase: from=0x10000 to=0x11fff kworker/1:3H-2368 [001] .... 213.478507: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.478541: mmc_do_erase: from=0x12000 to=0x13fff kworker/1:3H-2368 [001] .... 213.598798: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.598829: mmc_do_erase: from=0x14000 to=0x15fff kworker/1:3H-2368 [001] .... 213.664721: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.664750: mmc_do_erase: from=0x16000 to=0x17fff kworker/1:3H-2368 [001] .... 213.730632: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.730661: mmc_do_erase: from=0x18000 to=0x19fff kworker/1:3H-2368 [001] .... 213.862108: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.862138: mmc_do_erase: from=0x1a000 to=0x1bfff kworker/1:3H-2368 [001] .... 213.928017: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.928046: mmc_do_erase: from=0x1c000 to=0x1dfff kworker/1:3H-2368 [001] .... 213.993925: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 213.993954: mmc_do_erase: from=0x1e000 to=0x1ffff kworker/1:3H-2368 [001] .... 214.110795: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 214.110827: mmc_do_erase: from=0x20000 to=0x21fff kworker/1:3H-2368 [001] .... 214.173232: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 214.173263: mmc_do_erase: from=0x22000 to=0x23fff kworker/1:3H-2368 [001] .... 214.239191: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 214.239221: mmc_do_erase: from=0x24000 to=0x25fff kworker/1:3H-2368 [001] .... 215.069222: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 215.069253: mmc_do_erase: from=0x26000 to=0x27fff kworker/1:3H-2368 [001] .... 215.135138: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 215.135168: mmc_do_erase: from=0x28000 to=0x29fff kworker/1:3H-2368 [001] .... 215.197232: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 215.197264: mmc_do_erase: from=0x2a000 to=0x2bfff kworker/1:3H-2368 [001] .... 216.040197: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 216.040229: mmc_do_erase: from=0x2c000 to=0x2dfff kworker/1:3H-2368 [001] .... 216.158794: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 216.158824: mmc_do_erase: from=0x2e000 to=0x2ffff kworker/1:3H-2368 [001] .... 216.221232: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 216.221263: mmc_do_erase: from=0x30000 to=0x31fff kworker/1:3H-2368 [001] .... 217.064195: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 217.064226: mmc_do_erase: from=0x32000 to=0x33fff kworker/1:3H-2368 [001] .... 217.182794: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 217.182824: mmc_do_erase: from=0x34000 to=0x35fff kworker/1:3H-2368 [001] .... 217.245231: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 217.245263: mmc_do_erase: from=0x36000 to=0x37fff kworker/1:3H-2368 [001] .... 218.083500: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 218.083532: mmc_do_erase: from=0x38000 to=0x39fff kworker/1:3H-2368 [001] .... 218.141223: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 218.141253: mmc_do_erase: from=0x3a000 to=0x3bfff kworker/1:3H-2368 [001] .... 218.207130: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 218.207160: mmc_do_erase: from=0x3c000 to=0x3dfff kworker/1:3H-2368 [001] .... 219.046630: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 219.046663: mmc_do_erase: from=0x3e000 to=0x3ffff kworker/1:3H-2368 [001] .... 219.112564: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 219.112595: mmc_do_erase: from=0x40000 to=0x41fff kworker/1:3H-2368 [001] .... 219.230811: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 219.230842: mmc_do_erase: from=0x42000 to=0x43fff kworker/1:3H-2368 [001] .... 220.070631: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 220.070665: mmc_do_erase: from=0x44000 to=0x45fff kworker/1:3H-2368 [001] .... 220.136551: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 220.136580: mmc_do_erase: from=0x46000 to=0x47fff kworker/1:3H-2368 [001] .... 220.254794: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 220.254824: mmc_do_erase: from=0x48000 to=0x49fff kworker/1:3H-2368 [001] .... 221.094626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 221.094658: mmc_do_erase: from=0x4a000 to=0x4bfff kworker/1:3H-2368 [001] .... 221.160559: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 221.160588: mmc_do_erase: from=0x4c000 to=0x4dfff kworker/1:3H-2368 [001] .... 221.278793: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 221.278823: mmc_do_erase: from=0x4e000 to=0x4ffff kworker/1:3H-2368 [001] .... 222.118626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 222.118658: mmc_do_erase: from=0x50000 to=0x51fff kworker/1:3H-2368 [001] .... 222.184557: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 222.184586: mmc_do_erase: from=0x52000 to=0x53fff kworker/1:3H-2368 [001] .... 222.302797: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 222.302829: mmc_do_erase: from=0x54000 to=0x55fff kworker/1:3H-2368 [001] .... 223.142627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 223.142659: mmc_do_erase: from=0x56000 to=0x57fff kworker/1:3H-2368 [001] .... 223.208558: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 223.208587: mmc_do_erase: from=0x58000 to=0x59fff kworker/1:3H-2368 [001] .... 223.326793: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 223.326823: mmc_do_erase: from=0x5a000 to=0x5bfff kworker/1:3H-2368 [001] .... 224.166631: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 224.166663: mmc_do_erase: from=0x5c000 to=0x5dfff kworker/1:3H-2368 [001] .... 224.232553: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 224.232582: mmc_do_erase: from=0x5e000 to=0x5ffff kworker/1:3H-2368 [001] .... 224.350792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 224.350822: mmc_do_erase: from=0x60000 to=0x61fff kworker/1:3H-2368 [001] .... 225.190627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 225.190658: mmc_do_erase: from=0x62000 to=0x63fff kworker/1:3H-2368 [001] .... 225.256542: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 225.256571: mmc_do_erase: from=0x64000 to=0x65fff kworker/1:3H-2368 [001] .... 225.374796: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 225.374827: mmc_do_erase: from=0x66000 to=0x67fff kworker/1:3H-2368 [001] .... 226.214627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 226.214658: mmc_do_erase: from=0x68000 to=0x69fff kworker/1:3H-2368 [001] .... 226.333222: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 226.333255: mmc_do_erase: from=0x6a000 to=0x6bfff kworker/1:3H-2368 [001] .... 226.399137: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 226.399168: mmc_do_erase: from=0x6c000 to=0x6dfff kworker/1:3H-2368 [001] .... 227.238625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 227.238657: mmc_do_erase: from=0x6e000 to=0x6ffff kworker/1:3H-2368 [001] .... 227.304560: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 227.304589: mmc_do_erase: from=0x70000 to=0x71fff kworker/1:3H-2368 [001] .... 227.422792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 227.422822: mmc_do_erase: from=0x72000 to=0x73fff kworker/1:3H-2368 [001] .... 228.262629: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 228.262661: mmc_do_erase: from=0x74000 to=0x75fff kworker/1:3H-2368 [001] .... 228.328546: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 228.328575: mmc_do_erase: from=0x76000 to=0x77fff kworker/1:3H-2368 [001] .... 228.446796: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 228.446827: mmc_do_erase: from=0x78000 to=0x79fff kworker/1:3H-2368 [001] .... 229.286630: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 229.286662: mmc_do_erase: from=0x7a000 to=0x7bfff kworker/1:3H-2368 [001] .... 229.352545: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 229.352573: mmc_do_erase: from=0x7c000 to=0x7dfff kworker/1:3H-2368 [001] .... 229.470792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 229.470822: mmc_do_erase: from=0x7e000 to=0x7ffff kworker/1:3H-2368 [001] .... 230.310627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 230.310659: mmc_do_erase: from=0x80000 to=0x81fff kworker/1:3H-2368 [001] .... 230.376544: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 230.376574: mmc_do_erase: from=0x82000 to=0x83fff kworker/1:3H-2368 [001] .... 230.494792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 230.494822: mmc_do_erase: from=0x84000 to=0x85fff kworker/1:3H-2368 [001] .... 231.334626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 231.334658: mmc_do_erase: from=0x86000 to=0x87fff kworker/1:3H-2368 [001] .... 231.400542: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 231.400571: mmc_do_erase: from=0x88000 to=0x89fff kworker/1:3H-2368 [001] .... 231.518795: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 231.518827: mmc_do_erase: from=0x8a000 to=0x8bfff kworker/1:3H-2368 [001] .... 232.358627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 232.358659: mmc_do_erase: from=0x8c000 to=0x8dfff kworker/1:3H-2368 [001] .... 232.477222: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 232.477255: mmc_do_erase: from=0x8e000 to=0x8ffff kworker/1:3H-2368 [001] .... 232.543130: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 232.543160: mmc_do_erase: from=0x90000 to=0x91fff kworker/1:3H-2368 [001] .... 233.382626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 233.382658: mmc_do_erase: from=0x92000 to=0x93fff kworker/1:3H-2368 [001] .... 233.448558: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 233.448587: mmc_do_erase: from=0x94000 to=0x95fff kworker/1:3H-2368 [001] .... 233.566793: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 233.566823: mmc_do_erase: from=0x96000 to=0x97fff kworker/1:3H-2368 [001] .... 234.406628: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 234.406659: mmc_do_erase: from=0x98000 to=0x99fff kworker/1:3H-2368 [001] .... 234.472545: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 234.472574: mmc_do_erase: from=0x9a000 to=0x9bfff kworker/1:3H-2368 [001] .... 234.590796: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 234.590827: mmc_do_erase: from=0x9c000 to=0x9dfff kworker/1:3H-2368 [001] .... 235.430625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 235.430656: mmc_do_erase: from=0x9e000 to=0x9ffff kworker/1:3H-2368 [001] .... 235.496536: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 235.496566: mmc_do_erase: from=0xa0000 to=0xa1fff kworker/1:3H-2368 [001] .... 235.614792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 235.614822: mmc_do_erase: from=0xa2000 to=0xa3fff kworker/1:3H-2368 [001] .... 236.454627: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 236.454657: mmc_do_erase: from=0xa4000 to=0xa5fff kworker/1:3H-2368 [001] .... 236.520546: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 236.520575: mmc_do_erase: from=0xa6000 to=0xa7fff kworker/1:3H-2368 [001] .... 236.638793: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 236.638824: mmc_do_erase: from=0xa8000 to=0xa9fff kworker/1:3H-2368 [001] .... 237.478625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 237.478656: mmc_do_erase: from=0xaa000 to=0xabfff kworker/1:3H-2368 [001] .... 237.544554: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 237.544583: mmc_do_erase: from=0xac000 to=0xadfff kworker/1:3H-2368 [001] .... 237.662796: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 237.662827: mmc_do_erase: from=0xae000 to=0xaffff kworker/1:3H-2368 [001] .... 238.502625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 238.502656: mmc_do_erase: from=0xb0000 to=0xb1fff kworker/1:3H-2368 [001] .... 238.621222: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 238.621255: mmc_do_erase: from=0xb2000 to=0xb3fff kworker/1:3H-2368 [001] .... 238.687131: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 238.687161: mmc_do_erase: from=0xb4000 to=0xb5fff kworker/1:3H-2368 [001] .... 239.526626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 239.526657: mmc_do_erase: from=0xb6000 to=0xb7fff kworker/1:3H-2368 [001] .... 239.592540: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 239.592569: mmc_do_erase: from=0xb8000 to=0xb9fff kworker/1:3H-2368 [001] .... 239.710792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 239.710822: mmc_do_erase: from=0xba000 to=0xbbfff kworker/1:3H-2368 [001] .... 240.550626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 240.550656: mmc_do_erase: from=0xbc000 to=0xbdfff kworker/1:3H-2368 [001] .... 240.616539: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 240.616567: mmc_do_erase: from=0xbe000 to=0xbffff kworker/1:3H-2368 [001] .... 240.734796: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 240.734828: mmc_do_erase: from=0xc0000 to=0xc1fff kworker/1:3H-2368 [001] .... 241.574624: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 241.574655: mmc_do_erase: from=0xc2000 to=0xc3fff kworker/1:3H-2368 [001] .... 241.640552: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 241.640581: mmc_do_erase: from=0xc4000 to=0xc5fff kworker/1:3H-2368 [001] .... 241.758792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 241.758823: mmc_do_erase: from=0xc6000 to=0xc7fff kworker/1:3H-2368 [001] .... 242.598626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 242.598658: mmc_do_erase: from=0xc8000 to=0xc9fff kworker/1:3H-2368 [001] .... 242.664543: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 242.664571: mmc_do_erase: from=0xca000 to=0xcbfff kworker/1:3H-2368 [001] .... 242.782792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 242.782822: mmc_do_erase: from=0xcc000 to=0xcdfff kworker/1:3H-2368 [001] .... 243.622626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 243.622658: mmc_do_erase: from=0xce000 to=0xcffff kworker/1:3H-2368 [001] .... 243.688545: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 243.688574: mmc_do_erase: from=0xd0000 to=0xd1fff kworker/1:3H-2368 [001] .... 243.806795: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 243.806827: mmc_do_erase: from=0xd2000 to=0xd3fff kworker/1:3H-2368 [001] .... 244.646625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 244.646656: mmc_do_erase: from=0xd4000 to=0xd5fff kworker/1:3H-2368 [001] .... 244.765222: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 244.765255: mmc_do_erase: from=0xd6000 to=0xd7fff kworker/1:3H-2368 [001] .... 244.831131: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 244.831160: mmc_do_erase: from=0xd8000 to=0xd9fff kworker/1:3H-2368 [001] .... 245.670626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 245.670658: mmc_do_erase: from=0xda000 to=0xdbfff kworker/1:3H-2368 [001] .... 245.736537: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 245.736566: mmc_do_erase: from=0xdc000 to=0xddfff kworker/1:3H-2368 [001] .... 245.854792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 245.854823: mmc_do_erase: from=0xde000 to=0xdffff kworker/1:3H-2368 [001] .... 246.694624: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 246.694655: mmc_do_erase: from=0xe0000 to=0xe1fff kworker/1:3H-2368 [001] .... 246.760553: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 246.760582: mmc_do_erase: from=0xe2000 to=0xe3fff kworker/1:3H-2368 [001] .... 246.878795: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 246.878827: mmc_do_erase: from=0xe4000 to=0xe5fff kworker/1:3H-2368 [001] .... 247.718624: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 247.718656: mmc_do_erase: from=0xe6000 to=0xe7fff kworker/1:3H-2368 [001] .... 247.784540: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 247.784570: mmc_do_erase: from=0xe8000 to=0xe9fff kworker/1:3H-2368 [001] .... 247.902791: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 247.902821: mmc_do_erase: from=0xea000 to=0xebfff kworker/1:3H-2368 [001] .... 248.742625: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 248.742657: mmc_do_erase: from=0xec000 to=0xedfff kworker/1:3H-2368 [001] .... 248.808554: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 248.808584: mmc_do_erase: from=0xee000 to=0xeffff kworker/1:3H-2368 [001] .... 248.926792: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 248.926822: mmc_do_erase: from=0xf0000 to=0xf1fff kworker/1:3H-2368 [001] .... 249.766626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 249.766657: mmc_do_erase: from=0xf2000 to=0xf3fff kworker/1:3H-2368 [001] .... 249.832544: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 249.832574: mmc_do_erase: from=0xf4000 to=0xf5fff kworker/1:3H-2368 [001] .... 249.950797: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 249.950828: mmc_do_erase: from=0xf6000 to=0xf7fff kworker/1:3H-2368 [001] .... 250.790626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 250.790658: mmc_do_erase: from=0xf8000 to=0xf9fff kworker/1:3H-2368 [001] .... 250.909223: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 250.909256: mmc_do_erase: from=0xfa000 to=0xfbfff kworker/1:3H-2368 [001] .... 250.975143: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 250.975173: mmc_do_erase: from=0xfc000 to=0xfdfff kworker/1:3H-2368 [001] .... 251.814626: mmc_do_erase: mmc_poll_for_busy() done kworker/1:3H-2368 [001] .... 251.814656: mmc_do_erase: from=0xfe000 to=0xfffff kworker/1:3H-2368 [001] .... 251.880556: mmc_do_erase: mmc_poll_for_busy() done

As you can see, some erase operations are fast and some take significant
longer. While for the fast card, all are completed almost instantaneously. Looks like the slow card will do some kind of background work between erase
cycles.

The reported parameters of the slow card sounds reasonable, like 15s
for 2GiB. Because of this I've changed the perf_erase to its max value
for this card (i.e. au * 512):

# time blkdiscard /dev/mmcblk1
real	0m 1.72s
user	0m 0.00s
sys	0m 0.00s

kworker/0:3H-2375 [000] .... 528.308617: mmc_do_erase: from=0x0 to=0x3fdfff kworker/0:3H-2375 [000] .... 528.435991: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 528.436047: mmc_do_erase: from=0x3fe000 to=0x7fbfff kworker/0:3H-2375 [000] .... 528.605276: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 528.605311: mmc_do_erase: from=0x7fc000 to=0x7ffffe kworker/0:3H-2375 [000] .... 528.736726: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 528.736757: mmc_do_erase: from=0x7fffff to=0xbfdffe kworker/0:3H-2375 [000] .... 528.926908: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 528.926940: mmc_do_erase: from=0xbfdfff to=0xffbffe kworker/0:3H-2375 [000] .... 529.189489: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 529.189520: mmc_do_erase: from=0xffbfff to=0xfffffd kworker/0:3H-2375 [000] .... 529.386494: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 529.386524: mmc_do_erase: from=0xfffffe to=0x13fdffd kworker/0:3H-2375 [000] .... 529.629276: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 529.629307: mmc_do_erase: from=0x13fdffe to=0x17fbffd kworker/0:3H-2375 [000] .... 529.760731: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 529.760762: mmc_do_erase: from=0x17fbffe to=0x17ffffc kworker/0:3H-2375 [000] .... 529.892180: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 529.892211: mmc_do_erase: from=0x17ffffd to=0x1bfdffc kworker/0:3H-2375 [000] .... 530.023626: mmc_do_erase: mmc_poll_for_busy() done kworker/0:3H-2375 [000] .... 530.023656: mmc_do_erase: from=0x1bfdffd to=0x1cd9fff kworker/0:3H-2375 [000] .... 530.032057: mmc_do_erase: mmc_poll_for_busy() done

Now there is a comment about the "perf_erase" that states it should
be small to allow other I/O. But maybe we could also take the erase
time into account and allow larger erase sizes.

-michael



diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index 19f1ee57fb34..e126a01414be 100644
--- a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1675,6 +1675,8 @@ static int mmc_do_erase(struct mmc_card *card, unsigned int from,
                to <<= 9;
        }

+       trace_printk("from=0x%x to=0x%x\n", from, to);
+
        if (mmc_card_sd(card))
                cmd.opcode = SD_ERASE_WR_BLK_START;
        else
@@ -1747,6 +1749,7 @@ static int mmc_do_erase(struct mmc_card *card, unsigned int from,
        /* Let's poll to find out when the erase operation completes. */
        err = mmc_poll_for_busy(card, busy_timeout, MMC_BUSY_ERASE);

+       trace_printk("mmc_poll_for_busy() done\n");
 out:
        mmc_retune_release(card->host);
        return err;
diff --git a/drivers/mmc/core/sd.c b/drivers/mmc/core/sd.c
index 6f054c449d46..5e48a2cd4ad3 100644
--- a/drivers/mmc/core/sd.c
+++ b/drivers/mmc/core/sd.c
@@ -291,6 +291,8 @@ static int mmc_read_ssr(struct mmc_card *card)
        card->erase_arg = (card->scr.sda_specx && discard_support) ?
                            SD_DISCARD_ARG : SD_ERASE_ARG;

+ trace_printk("card->erase_arg=%d, au=%d es=%d et=%d eo=%d\n", card->erase_arg, au, es, et, eo);
+
        return 0;
 }




[Index of Archives]     [Linux Memonry Technology]     [Linux USB Devel]     [Linux Media]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux