Hide Forgot
Description of problem: Doing a yum operation takes 100 times longer than expected. I managed to get this down to a minimal test case: 1. I notice the problem: garry@vfr$ sudo yum erase btrfs-progs ... garry@vfr$ sudo yum install btrfs-progs garry@vfr$ fc -Dl ... 10003 3:17 sudo yum erase btrfs-progs 10004 6:22 sudo yum install btrfs-progs garry@vfr$ That's over three minutes to erase a small package and over six minutes to install the same package. 2. I find a way to (temporarily) fix the problem: garry@vfr$ sudo rm -f /var/lib/rpm/__db.001 /var/lib/rpm/__db.002 /var/lib/rpm/__db.003 /var/lib/rpm/__db.004 garry@vfr$ sudo rpm --rebuilddb garry@vfr$ sudo yum erase btrfs-progs ... garry@vfr$ sudo yum install btrfs-progs garry@vfr$ fc -Dl ... 10008 0:08 sudo yum erase btrfs-progs 10009 0:11 sudo yum install btrfs-progs garry@vfr$ Now erasing the same package takes eight seconds and installing the package again immediately takes 11 seconds. 3. The fix is only temporary. I then updated an installed package and repeated the erase-install test: garry@vfr$ sudo yum --enablerepo=updates-testing update Thunar garry@vfr$ sudo yum erase btrfs-progs ... garry@vfr$ sudo yum install btrfs-progs garry@vfr$ fc -Dl ... 10014 2:10 sudo yum -y --enablerepo=updates-testing update Thunar 10015 3:14 sudo yum erase btrfs-progs ... 10018 5:32 sudo yum install btrfs-progs garry@vfr$ The abysmal performance is back. :-( Version-Release number of selected component (if applicable): kernel-2.6.38.6-27.fc15.x86_64 rpm-4.9.0-6.fc15.x86_64 How reproducible: Every time. Additional info: Root file system is btrfs on lvm on md raid1. The long time to do an operation is accompanied by lots of disk churning. Here is output of vmstat 2 command during the erase btrfs-progs: procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 444 306424 140 1283560 0 0 0 0 221 329 1 1 98 0 0 0 0 444 306456 140 1283548 0 0 0 327 313 457 1 1 85 13 0 0 0 444 285980 140 1285784 0 0 0 0 515 505 12 3 85 0 0 Start yum erase 1 2 444 278516 140 1285772 0 0 0 7348 432 1031 2 5 83 11 0 1 2 444 282948 140 1283552 0 0 0 0 402 563 1 2 49 49 0 0 1 444 285080 140 1283552 0 0 0 0 449 572 1 2 33 63 0 0 1 444 283468 140 1283536 0 0 0 4156 526 1134 2 4 51 43 0 0 1 444 278444 140 1283536 0 0 0 6126 556 2206 1 3 47 49 0 1 4 444 278344 140 1283540 0 0 0 6 491 636 1 4 1 95 0 0 3 444 282068 140 1283540 0 0 0 2 381 586 1 2 0 97 0 0 2 444 281688 140 1283540 0 0 0 4608 584 1312 2 4 9 85 0 0 2 444 281792 140 1283544 0 0 0 2072 539 952 1 3 24 72 0 0 2 444 281100 140 1283544 0 0 0 4170 496 1343 1 3 28 67 0 0 1 444 281896 140 1283544 0 0 0 0 426 482 1 2 49 49 0 0 2 444 277908 140 1283544 0 0 0 7226 441 1823 1 5 47 46 0 1 1 444 280360 140 1283544 0 0 0 0 438 505 1 2 6 91 0 0 1 444 279568 140 1283552 0 0 0 6481 1462 4050 2 5 40 53 0 0 2 444 281512 140 1283544 0 0 0 5034 435 737 1 4 22 74 0 0 4 444 275912 140 1283544 0 0 0 6096 1743 3612 2 6 2 90 0 1 3 444 278416 140 1283544 0 0 0 4 586 735 1 3 0 96 0 0 2 444 281720 140 1283544 0 0 0 11 408 526 2 2 12 85 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 2 444 277048 140 1283544 0 0 0 6690 717 1905 1 5 45 48 0 0 1 444 279320 140 1283544 0 0 0 0 446 491 1 2 1 97 0 0 1 444 275480 140 1283544 0 0 0 6440 1817 6427 2 4 48 46 0 1 2 444 276540 140 1283536 0 0 0 0 489 700 1 3 2 95 0 1 0 444 280560 140 1283536 0 0 0 0 419 511 2 3 12 83 0 0 2 444 273940 140 1283568 0 0 0 6427 1769 5911 1 3 47 49 0 0 2 444 276164 140 1283568 0 0 0 0 388 498 1 2 0 96 0 0 1 444 272492 140 1283536 0 0 0 6498 953 3066 2 4 29 65 0 1 2 444 273552 140 1283536 0 0 0 0 852 1746 1 2 11 86 0 1 0 444 274668 140 1283536 0 0 0 0 411 501 2 3 13 82 0 0 1 444 269440 140 1283568 0 0 0 6900 767 2811 2 3 59 36 0 0 2 444 271372 140 1283536 0 0 0 2 458 551 1 3 16 80 0 0 1 444 273228 140 1283536 0 0 0 2212 505 968 2 4 47 46 0 1 1 444 269024 140 1283536 0 0 0 6860 606 1906 2 4 30 64 0 0 1 444 265632 140 1283536 0 0 0 10774 1070 3274 2 6 44 47 0 0 4 444 267856 140 1283536 0 0 0 246 1921 4751 1 3 8 88 0 0 3 444 271296 140 1283536 0 0 0 0 499 723 1 3 0 96 0 0 2 444 272528 140 1283536 0 0 0 12 333 512 1 1 8 90 0 0 1 444 271452 140 1283536 0 0 0 4186 771 1604 2 4 47 46 0 0 1 444 266204 140 1283536 0 0 0 6780 374 1690 2 4 49 45 0 0 2 444 267796 140 1283536 0 0 0 0 418 529 1 2 16 80 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 2 0 444 266276 140 1283536 0 0 0 5219 665 1343 2 4 46 47 0 0 0 444 265648 140 1283536 0 0 0 1422 2066 6546 1 1 98 0 0 1 2 444 262032 140 1283544 0 0 0 4826 602 1253 1 4 52 43 0 1 2 444 263180 140 1283548 0 0 0 0 397 492 1 2 49 48 0 0 2 444 265360 140 1283548 0 0 0 0 389 492 1 2 49 49 0 0 1 444 271424 140 1283548 0 0 0 6 698 804 1 1 19 79 0 0 2 444 266972 140 1283548 0 0 0 6200 825 2253 2 5 21 71 0 1 2 444 268056 140 1283548 0 0 0 0 418 471 1 2 49 48 0 1 2 444 262644 140 1283548 0 0 0 6496 1509 5153 1 4 47 47 0 1 2 444 263916 140 1283548 0 0 0 0 404 474 1 2 15 82 0 1 0 444 262672 140 1283548 0 0 0 6105 490 1680 2 5 42 51 0 0 1 444 262632 140 1283548 0 0 0 28 1695 5007 1 1 86 11 0 0 2 444 264828 140 1283540 0 0 0 0 420 513 1 2 45 52 0 0 1 444 267696 140 1283540 0 0 0 6 476 526 6 3 19 73 0 1 1 444 262792 140 1283548 0 0 0 4269 609 1032 5 4 49 43 0 0 2 444 260404 140 1283564 0 0 4 4230 488 1256 1 4 48 47 0 0 1 444 257836 140 1283564 0 0 0 6578 1244 2584 2 4 47 47 0 0 2 444 255348 140 1286892 0 0 0 2 991 2509 2 2 41 56 0 0 2 444 260616 140 1283456 0 0 0 0 433 521 1 3 0 97 0 0 2 444 254240 140 1283440 0 0 0 11957 915 3054 2 5 12 82 0 0 3 444 258824 140 1283440 0 0 0 144 1134 1974 1 3 5 91 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 2 444 261488 140 1283440 0 0 0 2 394 525 1 2 16 81 0 0 1 444 261696 140 1283440 0 0 0 2079 387 1146 2 3 48 47 0 0 2 444 261500 140 1283440 0 0 0 4242 599 1444 2 3 45 50 0 0 1 444 262720 140 1283440 0 0 0 2 384 491 1 2 47 49 0 0 1 444 263364 140 1284032 0 0 0 135 374 479 1 4 49 46 0 1 1 444 260248 140 1281908 0 0 0 7019 607 2078 1 6 20 72 0 0 2 444 261688 140 1281900 0 0 0 0 323 517 1 2 47 50 0 0 1 444 257360 140 1281900 0 0 0 5832 1305 3412 1 5 41 53 0 0 2 444 257828 140 1281900 0 0 0 0 912 1965 1 3 46 50 0 0 2 444 259356 140 1281900 0 0 0 0 410 447 1 2 2 96 0 0 1 444 257676 140 1281900 0 0 0 6093 1264 4450 1 4 61 33 0 0 2 444 259900 140 1281900 0 0 0 0 472 577 1 2 10 87 0 0 1 444 257584 140 1281864 0 0 0 6772 832 2321 2 5 18 76 0 0 2 444 257200 140 1281864 0 0 0 0 1789 5039 1 2 39 59 0 0 1 444 259204 140 1281864 0 0 0 0 430 464 1 2 14 83 0 0 1 444 257836 140 1281864 0 0 0 6430 1407 4503 1 4 52 42 0 0 3 444 240312 140 1299936 0 0 0 4886 1322 3561 4 5 26 65 0 0 2 444 247540 140 1293252 0 0 0 2 555 1279 3 3 17 78 0 0 2 444 247036 140 1292244 0 0 0 6466 1253 3332 1 3 29 66 0 0 3 444 257216 140 1283156 0 0 0 4 1600 3952 3 4 12 82 0 0 3 444 258696 140 1284136 0 0 0 818 415 822 2 2 0 97 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 5 444 258092 140 1283124 0 0 0 6910 2147 6264 4 6 29 61 0 0 4 444 259460 140 1283296 0 0 0 2 651 1471 4 3 0 93 0 2 3 444 258736 140 1284320 0 0 0 6022 964 3207 1 7 37 56 0 1 2 444 257288 140 1282172 0 0 0 6511 785 2794 3 4 38 56 0 0 2 444 257556 140 1283176 0 0 0 0 530 1282 2 3 0 96 0 6 1 444 262176 140 1281908 0 0 0 1490 536 759 2 3 13 83 0 0 2 444 257228 140 1282096 0 0 0 5000 933 3588 2 3 10 85 0 0 2 444 258112 140 1283156 0 0 0 0 358 430 1 2 13 84 0 0 2 444 260508 140 1283352 0 0 0 26 483 601 3 3 46 48 0 0 2 444 254640 140 1285188 0 0 0 6473 1270 4182 3 4 47 46 0 0 3 444 258076 140 1283448 0 0 0 0 472 613 2 3 7 89 0 0 2 444 256956 140 1283092 0 0 0 6446 790 2756 2 5 12 82 0 0 1 444 254860 140 1284964 0 0 0 2 1798 5178 3 1 20 75 0 2 2 444 257464 140 1283940 0 0 0 2 512 615 3 2 17 78 0 0 2 444 258792 140 1285000 0 0 0 318 376 507 2 2 21 75 0 0 2 444 261280 140 1281448 0 0 0 4134 551 1054 2 3 14 82 0 0 3 444 261788 140 1282820 0 0 0 26 478 594 3 2 40 55 0 0 4 444 240344 140 1297528 0 0 0 11142 981 3294 4 6 0 91 0 0 4 444 249036 140 1291152 0 0 0 6 775 1190 1 3 0 96 0 0 3 444 261620 140 1281936 0 0 0 2 497 698 1 2 31 65 0 0 2 444 261472 140 1281888 0 0 0 2074 660 1020 1 3 12 84 0 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 2 444 260144 140 1281888 0 0 0 4174 485 1459 1 4 36 60 0 1 2 444 249872 140 1288912 0 0 0 2 1104 607 27 17 9 48 0 1 3 444 251680 140 1282004 0 0 0 6348 1544 2128 31 26 9 33 0 0 3 444 246532 140 1288996 0 0 0 0 570 584 4 4 0 92 0 0 2 444 253080 140 1285560 0 0 0 2 386 508 1 2 0 97 0 1 0 444 304096 140 1286592 0 0 0 189 509 669 5 3 25 67 0 yum erase completes here 0 0 444 308824 140 1281932 0 0 0 0 238 397 1 1 98 0 0 0 0 444 308700 140 1281912 0 0 0 0 226 366 1 1 98 0 0 0 0 444 308700 140 1281912 0 0 0 0 210 325 1 1 98 0 0 Notice the very high I/O wait percentage and the remarkable lack of any reads during this time. I have no idea what this means.
Can you grab a strace of the badly performing case, eg "strace -tt -o /tmp/yum.log yum -y erase btrfs-progs" and attach the resulting log here? I suspect this is some kind of bad interaction with btrfs (and Berkeley DB) but the timestamped strace should shed some light on it.
I just upgraded to kernel-2.6.38.7-30.fc15.x86_64 from updates-testing and this fixed the problem. Thank you for your response.
Just in case anyone happens to come across this bug... I want to add that my "fix" wasn't really a fix. The kernel update didn't really fix this problem. I eventually got around it by moving and sym-linking the /var/yum directory to a file system that had much more free space (root). My /var file system before this change was at 50-60% utilization according to df(1). The total size of my /var partition is 2GB -- not near enough, in retrospect. I believe this is related to btrfs. It seems that there is a very lively discussion of this symptom on the btrfs-devel list. The problems seem to be related to sync() calls by the application. I also think the problem needs a file system with not a lot of free space.