Bug 709562

Summary: rpm Performance Problem
Product: [Fedora] Fedora Reporter: Garry T. Williams <gtwilliams>
Component: rpmAssignee: Panu Matilainen <pmatilai>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 15CC: ffesti, jnovy, pmatilai
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-06-06 10:42:41 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Garry T. Williams 2011-06-01 02:49:40 UTC 
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.
Comment 1 Panu Matilainen 2011-06-06 07:22:40 UTC 
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.
Comment 2 Garry T. Williams 2011-06-06 10:42:41 UTC 
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.
Comment 3 Garry T. Williams 2011-08-03 00:51:36 UTC 
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.