Hi! I am copying between two SD cards. One SDHC 32 GB and one SDXC 64 GB from Samsung. I assigned this to generic block layer, if it turns out to be an SD specific issue please reassign. I tend to think its generic block layer behavour tough. Filesystem on both sides is vfat. Maybe it is also a filesystem specific issue? With KDE´s Dolphin and now rsync -aAHXSP and I get with 3.17-rc2 with a patch for fixing hang in compressed writes with BTRFS I get this: merkaba:~> vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 1 814444 378964 20080 11284940 2 7 2112 981 112 112 24 7 66 3 0 0 1 814444 351660 20080 11302200 0 0 10688 3063 1788 4382 6 6 64 23 0 0 1 814444 375052 20084 11281932 0 0 18432 0 1838 3933 5 7 66 23 0 0 1 814444 358932 20084 11304060 0 0 17920 0 1419 3564 4 6 68 23 0 1 1 814444 337904 20088 11323192 0 0 9215 12288 1294 2215 5 5 69 22 0 1 1 814440 337904 20088 11323192 32 0 32 10240 1078 1225 2 4 71 23 0 0 1 814440 337904 20088 11323192 0 0 0 10248 1176 1294 4 3 70 23 0 0 1 814440 337904 20088 11323192 0 0 0 10240 1058 1172 3 3 71 23 0 0 1 814440 337904 20088 11323192 0 0 0 8192 1070 1235 4 3 70 23 0 0 1 814440 323100 20088 11336700 0 0 7104 5071 1407 2000 3 5 70 23 0 1 1 814440 386876 20092 11279168 0 0 18432 1968 2247 4013 9 8 61 23 0 1 1 814440 347040 20092 11314908 0 0 17920 0 1468 3262 5 7 65 23 0 0 1 814440 373020 20092 11291780 0 0 12800 12288 1407 2684 4 5 67 23 0 0 1 814440 373020 20092 11291780 0 0 0 10312 1065 1191 3 3 70 25 0 0 1 814440 372912 20092 11291780 0 0 0 8192 1102 1254 4 3 68 25 0 0 1 814440 372788 20092 11291780 0 0 0 8192 897 1066 3 3 70 25 0 0 1 814440 372788 20092 11291780 0 0 0 8192 1136 1291 4 3 68 25 0 0 1 814440 369068 20096 11294988 16 0 2000 9166 1564 1606 12 3 61 24 0 0 1 814436 327340 20096 11332248 0 0 18435 0 2334 4763 13 6 59 22 0 0 1 814436 376052 20100 11292020 0 0 17410 0 1488 3665 4 8 66 21 0 1 1 814436 372848 20100 11295016 0 0 17922 0 1477 3524 5 6 66 23 0 0 1 814436 385164 20104 11283488 0 0 17530 0 1481 3251 4 8 65 23 0 2 1 814436 346272 20104 11319492 0 0 18058 24 1416 3144 4 6 67 23 0 0 1 814436 357224 20108 11308752 0 0 17923 0 1397 3455 4 6 67 23 0 0 1 814436 384124 20108 11284984 0 0 18181 0 1487 3431 5 7 66 23 0 1 1 814436 359524 20112 11306928 0 0 17924 32 1516 3863 4 6 66 23 0 0 1 814436 340472 20112 11324232 0 0 8411 14336 1252 2046 4 4 69 23 0 0 1 814436 340348 20112 11324344 0 0 0 8192 1228 1616 3 3 70 23 0 0 1 814436 340348 20112 11324288 0 0 0 10313 1160 1303 4 3 71 22 0 1 1 814432 340068 20112 11324272 8 0 8 13712 1593 1662 2 4 69 25 0 0 1 814432 339944 20112 11324276 0 0 0 10240 1198 1300 4 3 69 25 0 1 1 814432 339804 20112 11324276 0 0 0 6144 1027 1282 3 4 70 22 0 0 1 814432 339820 20112 11324276 0 0 0 10240 1072 1235 4 3 69 25 0 1 1 814432 340192 20112 11323824 0 0 0 8192 1062 1215 3 3 70 25 0 1 1 814432 340192 20112 11323824 0 0 0 10240 1169 1274 5 3 68 24 0 0 1 814432 340160 20112 11323824 0 0 0 10240 1426 1385 10 3 64 23 0 0 1 814432 340160 20112 11323824 0 0 0 8192 1174 1566 4 3 71 23 0 This is a chainsaw behavior where it first reads without writing, then writes without reading, thus wasting about half of the time doing *nothing* on one side. Which would only explainable if rsync uses fsync on file close, which I think it does not, and strace seems to agree with me: merkaba:~> strace -e file -ff -p23096 Process 23096 attached --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} --- lstat("Meditationen/[some-path].mp3.u9AEWE", {st_mode=S_IFREG|0644, st_size=9633792, ...}) = 0 getxattr("Meditationen/[some-path].mp3.u9AEWE", "system.posix_acl_access", 0x7fff9db90280, 132) = -1 EOPNOTSUPP (Operation not supported) utimensat(AT_FDCWD, "Meditationen/[some-path].mp3.u9AEWE", {UTIME_NOW, {0, 0}}, AT_SYMLINK_NOFOLLOW) = 0 rename("Meditationen/[some-path].mp3.u9AEWE", "Meditationen/[some-path].mp3") = -1 ENOENT (No such file or directory) unlink("Meditationen/[some-path].mp3.u9AEWE") = -1 ENOENT (No such file or directory) --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=23095, si_uid=0} --- In between I see no vmstat activity at all but massive CPU activity of ATOP - merkaba 2014/08/31 12:49:03 --------- 10s elapsed PRC | sys 5.11s | user 1.19s | #proc 327 | #tslpu 3 | #zombie 0 | no procacct | CPU | sys 70% | user 13% | irq 10% | idle 140% | wait 168% | curscal ?% | cpu | sys 29% | user 2% | irq 10% | idle 59% | cpu000 w 0% | curscal ?% | cpu | sys 17% | user 7% | irq 0% | idle 0% | cpu003 w 75% | curscal ?% | cpu | sys 17% | user 2% | irq 0% | idle 82% | cpu002 w 0% | curscal ?% | cpu | sys 7% | user 2% | irq 0% | idle 0% | cpu001 w 92% | curscal ?% | CPL | avg1 3.07 | avg5 2.69 | avg15 1.93 | csw 679567 | intr 344431 | numcpu 4 | MEM | tot 15.5G | free 551.8M | cache 10.7G | buff 20.1M | slab 1.3G | shmem 308.8M | SWP | tot 12.0G | free 11.2G | | | vmcom 6.0G | vmlim 19.7G | LVM | msata-debian | busy 0% | read 0 | write 4 | MBw/s 0.00 | avio 2.75 ms | LVM | sata-debian | busy 0% | read 0 | write 4 | MBw/s 0.00 | avio 0.25 ms | LVM | msata-home | busy 0% | read 0 | write 11 | MBw/s 0.00 | avio 0.00 ms | LVM | sata-home | busy 0% | read 0 | write 11 | MBw/s 0.00 | avio 0.00 ms | DSK | sdb | busy 0% | read 0 | write 9 | MBw/s 0.01 | avio 1.22 ms | DSK | sda | busy 0% | read 0 | write 9 | MBw/s 0.01 | avio 0.11 ms | NET | transport | tcpi 20 | tcpo 22 | udpi 0 | udpo 0 | tcpao 0 | NET | network | ipi 20 | ipo 22 | ipfrw 0 | deliv 20 | icmpo 0 | NET | eth0 0% | pcki 7 | pcko 9 | si 1 Kbps | so 1 Kbps | erro 0 | NET | lo ---- | pcki 14 | pcko 14 | si 3 Kbps | so 3 Kbps | erro 0 | PID TID SYSCPU USRCPU VGROW RGROW RUID EUID THR ST EXC S CPU CMD 1/2 22955 - 4.67s 0.00s 0K 0K root root 1 -- - D 48% mmcqd/0 This might be a different bug. Hmm, it seems to hang here completely now. I think I will report this as a different bug. Well okay, it continued now, but then it ultimately failed with a ton of dmesg errors. MMC is still trial and error with current kernels it seems, at least on this ThinkPad T520. I thought this kind of chainsaw issues would be solved meanwhile – except for using rsync via NFS as NFS sync mount will stall on file close and rsync will wait for file to be closed. I will also report with application developers. It might be beneficial to not rely on file close behavior and do reads and writes in different threads to fully utilize the available bandwidth. But wait, rsync already uses different processes for reading and writing as far as I know. Reader is Digisol 5 in 1 card reader which seems to be based on Transcend stuff: merkaba:~> lsusb | grep Transcend Bus 002 Device 007: ID 1307:0330 Transcend Information, Inc. 63-in-1 Multi-Card Reader/Writer and has Samsung MB-MPBGC (I think), a 32 GB MicroSDHC card which I think does USH-I as well equipped. Writer is internal SD card slot in ThinkPad T520: merkaba:~> lspci -nn | grep MMC 0d:00.0 System peripheral [0880]: Ricoh Co Ltd MMC/SD Host Controller [1180:e822] (rev 08) and has Samsung Memory MB-MP64D 64GB EVO MicroSDXC UHS-I Grade Class 10 MicroSDXC equipped. The card readers may or may not be capable to use UHS-1. I bet they are not, at least the ThinkPad T520 one Both cards use manufacturer partitioning. The 64 GB one I have reformatted from ExFAT to FAT32 with default settings. Thanks, Martin
Bug 83571 - errors on writing on Samsung MicroSDXC 64 GB card in MMC card reader in ThinkPad T520
Does this still happen with 3.17-rc3 ?
It still happens with 4.5. One is 64 GB microSDXC card in Sansa Clip Zip with Rockbox and one is 128 GB microSDXC card in ThinkPad T520 SD card slot (with MicroSD- to SD adpter). procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 0 196228 1573564 36880 10992876 0 0 0 0 428 1161 2 1 97 0 0 0 0 196228 1573564 36880 10992876 0 0 0 0 583 1521 4 1 95 0 0 0 1 196228 1573392 37324 10992448 0 0 402 0 3007 9127 2 2 79 17 0 0 1 196228 1572400 38108 10992872 0 0 712 0 4881 15128 1 1 75 23 0 0 1 196228 1572056 38828 10992604 0 0 733 0 5000 15539 1 1 76 22 0 1 1 196228 1570752 39556 10992816 0 0 717 4096 5306 16228 4 3 69 24 0 1 1 196228 1558336 40320 10992904 0 0 737 0 5238 16127 8 2 69 22 0 1 1 196228 1555860 41028 10993544 0 0 708 0 5143 16368 5 3 69 23 0 0 1 196228 1555568 41752 10993912 0 0 707 0 4923 15231 1 2 72 25 0 0 1 196228 1546780 47424 10995560 0 0 541 0 4126 12293 2 6 72 20 0 0 1 196228 1544976 48180 10995188 0 0 707 96 5141 16442 5 3 69 23 0 0 1 196228 1532764 49316 11006896 0 0 5332 0 1562 3975 4 3 71 22 0 0 1 196228 1519928 49320 11019656 0 0 5888 0 961 2136 3 3 72 23 0 1 1 196228 1507204 49320 11032668 0 0 5760 0 1035 2185 4 2 71 23 0 0 1 196228 1492784 49320 11044940 0 0 5760 10250 1269 2356 4 3 66 27 0 0 1 196228 1480372 49320 11057924 0 0 5888 0 1463 2685 4 3 71 22 0 0 1 196228 1467028 49320 11071200 0 0 5888 0 1106 2538 5 3 70 23 0 2 0 196228 1455272 49324 11083704 0 0 5888 0 1302 3513 6 3 68 22 0 0 1 196228 1442576 49324 11097144 0 0 5760 0 1091 2206 4 3 70 23 0 2 0 196228 1429976 49324 11109564 0 0 5760 0 1049 2206 4 3 71 23 0 0 1 196228 1416872 49324 11122620 0 0 5888 0 1111 2555 4 3 69 24 0 0 1 196228 1404080 49324 11135132 0 0 5888 0 1046 2307 4 2 71 23 0 0 1 196228 1390960 49324 11148844 0 0 5760 0 1137 2438 5 3 70 23 0 0 1 196228 1377788 49328 11160812 0 0 5888 0 1319 3383 6 4 69 22 0 0 1 196228 1364148 49328 11173916 0 0 5888 0 1279 3657 6 2 68 23 0 0 1 196228 1351432 49328 11187012 0 0 5888 0 1110 2832 4 3 70 22 0 0 1 196228 1339180 49328 11200108 0 0 5760 0 1083 2889 5 3 70 22 0 0 1 196220 1326064 49328 11212536 0 0 5888 0 1146 2685 5 3 70 22 0 0 1 196220 1312756 49328 11225456 0 0 5760 0 996 2116 4 3 70 23 0 0 2 196220 1300092 49332 11238344 0 0 5888 8240 1093 2284 4 3 66 28 0 0 2 196220 1287116 49332 11251592 0 0 5888 10240 1594 2779 4 3 55 38 0 0 2 196220 1282056 49332 11256168 0 0 2054 12288 1104 1834 3 3 51 44 0 0 2 196220 1282084 49332 11256488 0 0 0 6204 857 1808 2 2 59 38 0 0 2 196220 1281900 49332 11256488 0 0 0 8896 843 1914 2 1 69 28 0 0 2 196220 1282096 49332 11256196 0 0 0 3108 700 1441 2 2 54 43 0 0 2 196220 1281776 49332 11256068 0 0 0 2292 793 1710 2 1 65 32 0 1 2 196220 1281776 49332 11256068 0 0 0 5296 793 2072 2 2 48 49 0 0 2 196220 1281776 49332 11256068 0 0 0 4372 802 1483 2 1 58 39 0 0 2 196220 1281724 49332 11256068 0 0 0 5476 1071 2267 3 2 61 34 0 2 2 196220 1281792 49332 11256068 0 0 0 1796 630 1581 2 2 53 44 0 1 2 196220 1281888 49332 11256072 0 0 0 9744 1175 2297 3 2 53 42 0 1 2 196220 1282024 49332 11256072 0 0 0 2313 695 1182 1 1 73 25 0 1 2 196220 1281420 49332 11256072 0 0 0 4872 921 2329 3 2 50 45 0 0 2 196220 1281328 49332 11256072 0 0 0 6244 983 2645 2 2 48 48 0 0 2 196220 1281312 49332 11256072 0 0 0 2608 524 1283 2 1 73 25 0 1 2 196220 1281312 49332 11256072 0 0 0 4980 946 1925 2 2 62 34 0 0 2 196220 1281344 49332 11256072 0 0 0 14724 817 1858 2 1 57 40 0 1 2 196220 1281328 49332 11256072 0 0 0 3661 783 1907 2 2 59 38 0 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 4 0 196220 1273556 49332 11264284 0 0 3968 1170 1403 2823 4 2 65 29 0 0 1 196220 1261312 49332 11276820 0 0 5760 0 1177 2367 4 3 71 22 0 0 1 196220 1247932 49332 11289468 0 0 5760 0 1483 2697 5 3 70 22 0 0 1 196220 1237640 49336 11300696 0 0 5008 10240 1202 2232 4 3 71 23 0 0 1 196220 1237304 49336 11301296 0 0 0 8192 882 1362 2 2 72 24 0 0 1 196220 1232372 49336 11306656 0 0 2560 2071 1197 1924 3 2 72 23 0 0 1 196220 1218732 49336 11318644 0 0 5760 0 1286 2391 4 3 71 22 0 0 1 196220 1208796 49336 11328876 0 0 4543 11203 1253 2334 3 3 71 23 0 2 1 196220 1197440 49336 11340428 0 0 5259 5519 1455 2496 3 4 71 22 0 1 1 196220 1184784 49336 11353444 0 0 5888 0 1358 2509 4 3 71 22 0 0 1 196220 1174464 49336 11363200 0 0 4401 10980 1193 2160 4 3 71 23 0 0 2 196220 1163884 49340 11373736 0 0 4775 5546 1546 2573 4 3 70 23 0 0 1 196220 1153364 49340 11384176 0 0 4608 88 1740 4755 7 5 64 25 0 1 1 196220 1140460 49340 11397284 0 0 6016 3504 1741 5736 13 4 57 26 0 0 1 196220 1127564 49340 11410672 0 0 5888 0 1306 3380 6 3 69 22 0 1 2 196220 1113704 49340 11424380 0 0 6016 6 1662 4625 10 3 63 23 0 2 0 196220 1100528 49340 11437144 0 0 6016 0 1631 4508 9 3 64 24 0 3 0 196220 1087600 49344 11450200 0 0 5888 328 1332 3378 4 4 68 24 0 0 1 196220 1074844 49344 11462988 0 0 5888 0 1138 2651 5 3 70 22 0 1 1 196220 1061668 49344 11476168 0 0 5760 0 1159 2668 4 3 70 23 0 0 1 196220 1048748 49344 11489472 0 0 6016 0 1528 5748 8 4 65 23 0 0 1 196220 1046044 49344 11492340 0 0 1026 16384 1354 2706 3 3 71 23 0 0 1 196220 1046044 49344 11491888 0 0 0 6144 1026 1732 4 2 71 23 0 0 1 196220 1045920 49344 11491892 0 0 0 10242 1045 1480 2 2 72 24 0 0 1 196220 1045920 49344 11491892 0 0 0 6144 843 1294 2 2 73 23 0 0 1 196220 1045748 49344 11491892 0 0 0 10344 1185 1843 2 2 71 24 0 0 1 196220 1044008 49344 11493652 0 0 896 3854 981 1510 2 2 72 24 0 0 1 196220 1031124 49344 11506376 0 0 5888 0 1624 2934 4 4 70 22 0 0 1 196220 1018980 49348 11519012 0 0 5760 0 1022 2150 4 3 71 23 0 1 1 196220 1005888 49348 11531276 0 0 5760 0 1089 2264 5 3 71 22 0 0 1 196220 993080 49348 11544844 0 0 5888 10 1119 2317 5 2 70 24 0 0 1 196220 979736 49348 11557444 0 0 5760 0 1058 2151 4 3 70 23 0 0 1 196220 967384 49348 11570240 0 0 5760 32 1010 2284 4 3 71 22 0 0 1 196220 957160 49348 11583592 0 0 5888 0 1010 2143 4 3 71 22 0 0 1 196220 945960 49352 11595572 0 0 5760 0 982 2160 4 2 71 23 0 1 1 196220 931872 49352 11608392 0 0 5760 0 1044 2141 5 3 70 22 0 0 1 196220 919612 49352 11621472 0 0 5760 0 1001 2120 4 3 70 24 0 0 1 196220 905032 49352 11634160 0 0 5888 0 1048 2275 4 3 71 23 0 0 1 196220 891960 49352 11646816 0 0 5760 0 1079 2334 4 3 70 23 0 1 1 196220 878828 49352 11660220 0 0 5888 88 1167 2602 4 3 71 22 0 1 0 196220 865732 49356 11672788 0 0 6016 0 1471 5419 9 4 65 23 0 0 1 196220 852312 49356 11685556 0 0 5888 0 1217 2741 4 3 71 23 0 0 1 196220 845312 49356 11694272 0 0 3771 12288 1173 2365 4 3 70 23 0 0 1 196220 845156 49356 11694980 0 0 0 6144 1488 3101 8 2 65 25 0 0 1 196220 845164 49356 11694980 0 0 0 10240 1299 2230 3 2 71 24 0 0 2 196220 844420 49356 11695432 0 0 0 5660 1262 2998 3 3 54 41 0 1 2 196220 847428 49356 11695432 0 0 0 3212 872 2575 4 1 48 47 0 0 2 196220 845924 49356 11695436 0 0 0 14075 1133 3157 2 2 48 48 0 I didn´t measure, but I estimate that delay caused by this for microSD cards which can do somewhat around 5-10 MiB/s excessive buffering delays the operation by roughly a factor of 2. What happens when I watch /proc/meminfo is that it builds up caches of up to 60 MiB and then it writes it out and especially when rsync() closes the file it then waits for the file to be written and rsync doesn´t yet load the next file… … which of course is also something that could be optimized in rsync.