Bug 209323 - choosing packages to update is too slow by a factor of 10
choosing packages to update is too slow by a factor of 10
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: yum (Show other bugs)
rawhide
All Linux
medium Severity medium
: ---
: ---
Assigned To: Jeremy Katz
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2006-10-04 12:19 EDT by John Reiser
Modified: 2014-01-21 17:55 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-04-25 14:24:34 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description John Reiser 2006-10-04 12:19:09 EDT
Description of problem:
A "yum update" from FC6Pre (Sept.30) to rawhide of Oct.3 took 10 minutes of CPU
time to go from "############## 3446/3446" to "Populating transaction set with
selected packages" when 159 packages (275MB) were chosen to be updated; only one
repository was active.  That was on PowerPC Apple Macintosh mini (1.25GHz, 512MB
DDR RAM, no paging).  On a "3200" AMD x86_64 (2.0GHz clock, 1GB DDR RAM, no
paging), a "yum update" from rawhide of Oct.2 to Rawhide of Oct.3 took 3.5
minutes of CPU time when 19 packages (25MB) were chosen from two repositories
(2935/2935 and 3459/3459 packages).  Times were measured using "top"; CPU
utilization was usually at least 95%.

In each case the CPU usage is too large by a factor of ten.

Version-Release number of selected component (if applicable):
yum-2.9.8-1

How reproducible:
"always"

Steps to Reproduce:
1. yum update
2.
3.
  
Actual results:
Choosing which packages to update takes much too long.

Expected results:
Choosing packages to update takes at most one minute on a 1GHz machine that has
enough RAM to avoid paging.

Additional info:
Comment 1 Valdis Kletnieks 2007-03-19 11:55:38 EDT
Seeing it here too.  x86_64, only 52 packages listed by 'yum list updates' done
just a few minutes before.  A 2Ghz Core2 Duo, 2G of memory - and it takes it
14:27 to get from 'yum update' to 'Total Download SIze/Is this OK?'

yum-3.1.4-1.fc7 - so either it's some horrendous cycle sucker in a shared
library (sqlite?) or something, or everything from 2.9.8 to 3.1.4 is busticated.
Comment 2 Seth Vidal 2007-03-19 12:08:16 EDT
2.9.8->3.1.4 is a huge difference in code and we've had thousands and thousands
of success reports on 3.0.X reported so I'm a little confused that NOTHING b/t
those has worked for you.
Comment 3 Valdis Kletnieks 2007-03-19 12:43:42 EDT
Obviously some profiling is needed, I'll dig in and follow up when I have more
concrete information.
Comment 4 Valdis Kletnieks 2007-03-21 14:04:22 EDT
So I pointed oprofile at the system, and it said most of the time was being
spent in libpython.so.  And I caught a few seconds worth of strace output:

# strace -p 10973 > /tmp/trace 2>&1 (wait about 10 seconds and then ^C)
# wc /tmp/trace
  346510  1733628 16765630 /tmp/trace
# sort /tmp/trace | uniq -c | sort -nr | more
 270228 futex(0xc7baf0, FUTEX_WAKE, 1)          = 0
     83 read(16, "\0\0\0\0amimageplugin_unsharp.mo/dig"..., 1024) = 1024
     67 read(16, "\0\0\0\0ffffffffffffffffffffffffffff"..., 1024) = 1024
     34 read(16, "\0\0\0\0-4300.5.0.ppd.gz/stp-bjc-400"..., 1024) = 1024
     28 read(16, "\0\0\0\0tle-5-active.xpm/title-4-ina"..., 1024) = 1024
     24 read(16, "\r\0\0\0\1\0\'\0\0\'\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10
24) = 1024
     24 read(16, "\r\0\0\0\1\0!\0\0!\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10
24) = 1024
     20 read(16, "\0\0\0\0ctive.xpm/menu-inactive.png/"..., 1024) = 1024
     18 read(16, "\r\0\0\0\1\1D\0\1D\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 10
24) = 1024
     18 read(16, "\0\0\0\0g/network-wireless.png/netwo"..., 1024) = 1024
     18 read(16, "\0\0\0\0etwork-offline.png/network-i"..., 1024) = 1024
     18 read(16, "\0\0\0\0dhat-system_tools.png/redhat"..., 1024) = 1024
     18 read(16, "\0\0\0\0.png/locale.png/kwin.png/kus"..., 1024) = 1024

Yowza.  Looks like we're spinning on a futex for some reason.

(And it looks like somebody could be a bit better about in-memory caching
and not be re-reading the same blocks several dozen times, but I suspect that's
in the 5 or 6% of the time we spent in libsqlite3.so - hardly a performance hit)

Any suggestions where to look next?  I know zip about python - any way to get it
to do statement-level profiling/execution counts?
Comment 5 Valdis Kletnieks 2007-03-21 14:16:18 EDT
OK, *major* weirdness, maybe this is a useful clue..  After some 15 minutes of
grinding, the 'yum update' bombed out during the download phase:

<....>
Installing for dependencies:
 java_cup                x86_64     1:0.10-0.k.6jpp.1  development       206 k
<....>
Error Downloading Packages:
  java_cup - 1:0.10-0.k.6jpp.1.x86_64: failure:
Fedora/RPMS/java_cup-0.10-0.k.6jpp.1.x86_64.rpm from development: [Errno 256] No
more mirrors to try.

Note that RPM was a "install for dependencies".  So I ran:

# yum --exclude="*java*" update

and *that* finished its crunching in the minute or so I expected it to take.

Maybe the problem is in handling the "added for dependencies" RPMs?
Comment 6 Jeremy Katz 2007-04-25 14:24:34 EDT
3.1.6 si even better, 3.1.7 has even more better

Note You need to log in before you can comment on or make changes to this bug.