Bug 83561 - Suboptimal chainsaw behavior in copying between to SD cards

From: Martin Steigerwald
Date: Sun Apr 17 2016 - 08:54:21 EST

Hello Jens, hello block level and vm/mm developers,

I am still seeing this in kernel 4.5.

Bug 83561 - Suboptimal chainsaw behavior in copying between to SD cards
https://bugzilla.kernel.org/show_bug.cgi?id=83561

Its basically the same what happens when rsyncing onto an NFS mount when
the network connection is slower than local disks.

Is this something your recent patches addressing bufferbloat in block layer
will address, Jens?


Quote from bug report:

https://bugzilla.kernel.org/show_bug.cgi?id=83561#c3


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.

Thanks
--
Martin