| Summary: | 2.2.0_alpha173 - emerge --deep is extremely slow | ||
|---|---|---|---|
| Product: | Portage Development | Reporter: | Xavier Miller (RETIRED) <xaviermiller> |
| Component: | Core | Assignee: | Portage team <dev-portage> |
| Status: | RESOLVED OBSOLETE | ||
| Severity: | normal | CC: | bdouxx-gentoo, gef.kornflakes, jouni.kosonen, jrmalaq, kuba.iluvatar, nrndda, pageexec, santosdosreis |
| Priority: | Normal | ||
| Version: | unspecified | ||
| Hardware: | All | ||
| OS: | Linux | ||
| See Also: |
https://bugs.gentoo.org/show_bug.cgi?id=484788 https://bugs.gentoo.org/show_bug.cgi?id=486580 |
||
| Whiteboard: | |||
| Package list: | Runtime testing required: | --- | |
| Attachments: |
Sorted profiling output
Raw profiling data used for previous attachent |
||
|
Description
Xavier Miller (RETIRED)
2013-05-03 17:20:37 UTC
It's more catastrophic with sys-apps/portage-2.1.11.62 time emerge -DuNpv @world real 4m41.933s user 4m15.040s sys 0m7.668s I will create an alias "abyssal" for "deep"... I am also experiencing this problem, since a few week, I'd say. I tried several things that I gathered from various problems with slow emerge, like rebuilding the cache or trying sqlite backend, to no improvement. time emerge -puDN @world These are the packages that would be merged, in order: Calculating dependencies... done! real 4m46.603s user 4m7.695s sys 0m2.992s time emerge -puN @world These are the packages that would be merged, in order: Calculating dependencies... done! real 0m9.765s user 0m9.574s sys 0m0.176s emerge --info Portage 2.2.0_alpha173 (default/linux/x86/13.0/desktop, gcc-4.7.2, glibc-2.17, 3.8.10-gentoo i686) ================================================================= System uname: Linux-3.8.10-gentoo-i686-Intel-R-_Core-TM-2_CPU_T7200_@_2.00GHz-with-gentoo-2.2 KiB Mem: 2063312 total, 312816 free KiB Swap: 2160704 total, 2022876 free Timestamp of tree: Thu, 02 May 2013 10:00:01 +0000 ld GNU ld (GNU Binutils) 2.23.1 app-shells/bash: 4.2_p45 dev-java/java-config: 2.1.12-r1 dev-lang/python: 2.7.4, 3.2.4 dev-util/cmake: 2.8.10.2-r2 dev-util/pkgconfig: 0.28 sys-apps/baselayout: 2.2 sys-apps/openrc: 0.11.8 sys-apps/sandbox: 2.6-r1 sys-devel/autoconf: 2.13, 2.69 sys-devel/automake: 1.11.6, 1.12.6, 1.13.1 sys-devel/binutils: 2.23.1 sys-devel/gcc: 4.7.2-r1 sys-devel/gcc-config: 1.8 sys-devel/libtool: 2.4.2 sys-devel/make: 3.82-r4 sys-kernel/linux-headers: 3.8 (virtual/os-headers) sys-libs/glibc: 2.17 Repositories: gentoo science personal Installed sets: @system ACCEPT_KEYWORDS="x86 ~x86" ACCEPT_LICENSE="* -@EULA" CBUILD="i686-pc-linux-gnu" CFLAGS="-O2 -march=native -pipe -fomit-frame-pointer" CHOST="i686-pc-linux-gnu" CONFIG_PROTECT="/etc /usr/share/gnupg/qualified.txt" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/revdep-rebuild /etc/sandbox.d /etc/splash /etc/terminfo /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c" CXXFLAGS="-O2 -march=native -pipe -fomit-frame-pointer" DISTDIR="/usr/portage/distfiles" EMERGE_DEFAULT_OPTS="--with-bdeps=y --jobs=3 --load-average=4 --keep-going --quiet-build" FCFLAGS="-O2 -march=i686 -pipe" FEATURES="assume-digests binpkg-logs config-protect-if-modified distlocks ebuild-locks fixlafiles merge-sync metadata-transfer news parallel-fetch preserve-libs protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch" FFLAGS="-O2 -march=i686 -pipe" GENTOO_MIRRORS="ftp://ftp.free.fr/mirrors/ftp.gentoo.org/ http://mirrors.sec.informatik.tu-darmstadt.de/gentoo/ ftp://ftp.wh2.tu-dresden.de/pub/mirrors/gentoo" LANG="fr_FR.utf8" LC_ALL="fr_FR.utf8" LDFLAGS="-Wl,-O1 -Wl,--as-needed" MAKEOPTS="-j5" PKGDIR="/var/tmp/binpkgs" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/var/lib/layman/science /usr/local/portage" SYNC="rsync://rsync.gentoo.org/gentoo-portage" USE="X a52 aac acl acpi aiglx alsa berkdb branding bzip2 cairo cdda cdr cli consolekit cracklib crypt cups cxx dbus dri dts dvd dvdr emboss encode exif fam fbcon firefox flac fortran gdbm gif gimp gnome gstreamer gtk gtk2 iconv java jpeg jpeg2k lcms libnotify mad mmx mng modules mp3 mp4 mpeg msn mudflap nautilus ncurses nls nptl nsplugin ogg opengl openmp pam pango pcre pdf png policykit pulseaudio qt3support readline ruby sdl session spell sqlite3 sse sse2 ssl svg tcpd tiff truetype udev udisks unicode upower usb vorbis wxwidgets x264 x86 xcb xml xulrunner xv xvid zlib" ABI_X86="32" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1 emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="kexi words flow plan sheets stage tables krita karbon braindump author" CAMERAS="ptp2" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ubx" INPUT_DEVICES="evdev synaptics" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LINGUAS="fr fr_FR en en_GB" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php5-3" PYTHON_SINGLE_TARGET="python2_7" PYTHON_TARGETS="python2_7 python3_2" QEMU_SOFTMMU_TARGETS="i386" QEMU_USER_TARGETS="i386" RUBY_TARGETS="ruby18 ruby19" USERLAND="GNU" VIDEO_CARDS="intel i915" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CPPFLAGS, CTARGET, INSTALL_MASK, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS, USE_PYTHON If you'd like to try git-bisect with a portage checkout, set PATH and PYTHONPATH variables as described on this page: http://www.gentoo.org/proj/en/portage/doc/testing.xml I'm a user, I don't have time to debug code. The git-bisect process is very simple. It doesn't involve "debugging" and practically anyone can do it. OK I have cloned the GIT repository. What to do now? Results with GIT version: # which emerge /data/src/portage/bin/emerge (looks good!) # emerge --version Portage 2.2.0_alpha174_p1 (default/linux/x86/13.0/desktop, gcc-4.7.2, glibc-2.17, 3.9.0-gentoo i686) # time emerge -DuNpv @world real 1m55.080s user 1m50.284s sys 0m2.148s # time emerge -uNpv @world real 0m26.783s user 0m26.034s sys 0m0.654s (In reply to comment #7) > # time emerge -DuNpv @world > > real 1m55.080s That is significantly less time than the 3m43.490s reported in comment #0. If you repeat the same dependency calculation with 2.2.0_alpha173 immediately afterwards, do you still see a comparable time to 3m43.490s? You might also try adding --backtrack=0 to your options, to see if that makes any difference, since backtracking is the most common cause of lengthy dependency calculations. 1st run is slower: GIT version: Run 1: real 3m12.236s user 2m19.903s sys 0m26.566s Run 2: real 2m0.512s user 1m57.028s sys 0m2.362s Portage 2.2.0_alpha174 (default/linux/x86/13.0/desktop, gcc-4.7.2, glibc-2.17, 3.9.0-gentoo i686) Run 1: real 2m3.905s user 1m59.857s sys 0m2.094s Run2: real 2m3.441s user 2m0.274s sys 0m2.058s With --backtrack=0 Portage 2.2.0_alpha174 (default/linux/x86/13.0/desktop, gcc-4.7.2, glibc-2.17, 3.9.0-gentoo i686) real 2m0.917s user 1m56.418s sys 0m1.978s Same time. Will play with git-bissect (I just read the doc, seems easy to follow) version 2.2.0_alpha0 is also slow. can't the problem reside in the Portage tree? (In reply to comment #10) > version 2.2.0_alpha0 is also slow. You probably shouldn't go below 2.2.0_alpha130, since that's the first version to support EAPI 5. > can't the problem reside in the Portage tree? Do you use any special rsync options to sync, such as --exclude? If your tree is identical to the one used by everyone else, then you would expect more people to report similar issues if the problem was in the tree. I guess I cannot use git-bisect: the time results are always the same. You can use `emerge --version` to verify that the checkout is reasonable. The version number that it reports is generated from the output of `git describe --tags`. Hello, I can now use git bisect, and could use a dichotomic navigation between v2.2.0_alpha130 and latest version. None of those EAPI5 versions have a decent fast emerge --deep time. All the timings were around 2-3 minutes, sometimes 1m50, but not faster. On my AMD64x2, 2.2GHz, the timing is OK: first run: real 1m3.151s user 0m46.970s sys 0m9.123s second run: real 0m47.757s user 0m46.696s sys 0m0.924s Or, at least, not too slow. Over the last couple months, my emerge --deep has become excessively long (5m10.970s with 2.1.12.2). I tried dropping back to 2.1.11.62 and it still took roughly the same amount of time (5m9.343s). I have another amd64 box that uses the portage tree that's exported via NFS from this system and runs twice as fast with 2.1.11.62 (2m28.591s) and with less memory (2GB versus 6GB), so I don't think it's a matter of my portage tree being inefficient. I just did a git bisect from head back to 2.2.0_alpha130. 2.2.0_alpha177_p6 took 5m17.976s - roughly the same as 2.1.12.2, but every bisect after that was in the just under 8 minutes range. Comparing the dependencies in emerge --info, they are nearly identical (I have a couple extra versions of gcc for testing purposes on this computer, but both are using 4.7.2). The only software difference I see that that I have graphite flags enabled (floop-interchange -floop-strip-mine -floop-block -fgraphite-identity) on the slower box. Could that be the culprit? I don't want to rebuild all of world just to test it. In terms of hardware, one is an AMD based system the other an Intel slower system, which hosts and exports the portage tree Portage 2.1.12.2 (default/linux/amd64/13.0/desktop, gcc-4.7.2, glibc-2.15-r3, 3.9.4-gentoo x86_64) ================================================================= System uname: Linux-3.9.4-gentoo-x86_64-AMD_Athlon-tm-_64_X2_Dual_Core_Processor_4400+-with-gentoo-2.2 KiB Mem: 6102752 total, 3152820 free KiB Swap: 2104508 total, 2052424 free Timestamp of tree: Sat, 01 Jun 2013 02:15:01 +0000 ld GNU ld (GNU Binutils) 2.23.1 distcc 3.1 x86_64-pc-linux-gnu [disabled] ccache version 3.1.9 [enabled] app-shells/bash: 4.2_p45 dev-java/java-config: 2.1.12-r1 dev-lang/python: 2.7.3-r3, 3.2.3-r2 dev-util/ccache: 3.1.9 dev-util/cmake: 2.8.10.2-r2 dev-util/pkgconfig: 0.28 sys-apps/baselayout: 2.2 sys-apps/openrc: 0.11.8 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.13, 2.69 sys-devel/automake: 1.11.6, 1.12.6 sys-devel/binutils: 2.23.1 sys-devel/gcc: 4.3.6-r1, 4.6.4, 4.7.2-r1, 4.8.0 sys-devel/gcc-config: 1.7.3 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r4 sys-kernel/linux-headers: 3.4-r2 (virtual/os-headers) sys-libs/glibc: 2.15-r3 Portage 2.1.11.62 (default/linux/amd64/13.0/desktop/kde, gcc-4.7.2, glibc-2.15-r3, 3.9.4-gentoo x86_64) ================================================================= System uname: Linux-3.9.4-gentoo-x86_64-Intel-R-_Pentium-R-_D_CPU_3.40GHz-with-gentoo-2.2 KiB Mem: 2041440 total, 1371192 free KiB Swap: 8393924 total, 8393924 free Timestamp of tree: Sat, 01 Jun 2013 02:15:01 +0000 ld GNU ld (GNU Binutils) 2.23.1 distcc 3.1 x86_64-pc-linux-gnu [disabled] ccache version 3.1.9 [disabled] app-shells/bash: 4.2_p45 dev-lang/python: 2.7.3-r3, 3.2.3-r2 dev-util/ccache: 3.1.9 dev-util/cmake: 2.8.10.2-r2 dev-util/pkgconfig: 0.28 sys-apps/baselayout: 2.2 sys-apps/openrc: 0.11.8 sys-apps/sandbox: 2.5 sys-devel/autoconf: 2.13, 2.69 sys-devel/automake: 1.11.6, 1.12.6 sys-devel/binutils: 2.23.1 sys-devel/gcc: 4.6.3, 4.7.2-r1, 4.8.0 sys-devel/gcc-config: 1.7.3 sys-devel/libtool: 2.4-r1 sys-devel/make: 3.82-r4 sys-kernel/linux-headers: 3.9 (virtual/os-headers) sys-libs/glibc: 2.15-r3 (In reply to saellaven from comment #15) > The only software difference I see that that I > have graphite flags enabled (floop-interchange -floop-strip-mine > -floop-block -fgraphite-identity) on the slower box. Could that be the > culprit? I don't know. > I don't want to rebuild all of world just to test it. You only need to rebuild python, which doesn't take long. No real change in time with python compiled without graphite. It came in at 5m30.909s compared to 5m10.970s without something changed in the last week, bringing times dramatically down for me sometime around portage 2.1.12.6 or 2.1.12.7 real 2m20.239s I don't see any change. The only machine with slow performance is the ~x86, which performance is as bad as a Raspberry Pi ! The ~amd64 config has very good response time (30-50s). The Raspi (256 MO version) has, as the 2 other machines, portage compressed in squashfs (XZ), and a very basic system (no X, just stage 3). The ~x86 (Atom 1.6 GHz, 1.5 Go RAM) and ~amd64 (AMD64x2 2.2GHz, 2Go RAM) machines have almost identical packages and config (behalve drivers and 2-3 specific application for each config). Small memory footprint during emerges (razor-qt, xterm). I don't have a clue what to do to find the problem Here are the times, after boot (first emerge, second emerge) -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- ~amd64 # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 0m49.971s user 0m33.193s sys 0m8.632s ~ # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 0m33.716s user 0m33.027s sys 0m0.628s -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- Raspi: raspi ~ # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 3m22.762s user 3m0.140s sys 0m20.070s raspi ~ # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 3m2.849s user 3m0.420s sys 0m1.750s -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- ~x86 # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 2m53.401s user 2m13.301s sys 0m23.407s # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 2m17.543s user 2m15.020s sys 0m2.024s -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- 8< -- (In reply to Xavier Miller from comment #19) > The Raspi (256 MO version) has, as the 2 other machines, portage compressed > in squashfs (XZ), and a very basic system (no X, just stage 3). You might try using gzip instead of xz in your squashfs, since xz is slower to decompress (depends on a lot on your cpu type). Yeah, I won 15 seconds on the Raspi, but the problem is still that strange slowness on the ~x86 machine... Hello, I tried to rebuild @system without distcc, and I get the same slow results, portage-2.2.1 # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 2m58.968s user 2m32.589s sys 0m8.083s # time emerge -DuNpv @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 2m35.829s user 2m33.367s sys 0m2.113s With "--with-bdeps n", its a little bit faster: # time emerge -DuNpv --with-bdeps n @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 1m47.532s user 1m45.664s sys 0m1.575s # time emerge -DuNpv --with-bdeps y @world These are the packages that would be merged, in order: Calculating dependencies ... done! Total: 0 packages, Size of downloads: 0 kB real 2m37.387s user 2m33.706s sys 0m1.977s What do you need that could help you to point the problem? I use python 2.7 it it helps. # emerge -pv1 python These are the packages that would be merged, in order: Calculating dependencies ... done! [ebuild R ] dev-lang/python-2.7.5-r2:2.7 USE="ncurses readline sqlite ssl threads (wide-unicode) xml -berkdb -build -doc -examples -gdbm -hardened -ipv6 -tk -wininst" 0 kB Total: 1 package (1 reinstall), Size of downloads: 0 kB I've also experienced extremely slow "emerge -uDatvN world" calculations on my Core i7 machine with 12 GB of RAM and an SSD drive. I was using portage 2.2.1 before, but recently updated to 2.2.6. This is running on 2.2.6: root@skare$ time emerge -uDvptN --with-bdeps\=y world These are the packages that would be merged, in reverse order: Calculating dependencies... done! ... updateable packages... ... Total: 68 packages (54 upgrades, 14 reinstalls, 1 uninstall), Size of downloads: 107,141 kB Conflict: 9 blocks (8 unsatisfied) ... blockning info... ... real 11m52.245s user 11m33.473s sys 0m16.163s Another amazingly slow emerge --deep here, on AMD X4 945 w/ 16G.
Portage 2.2.7 (default/linux/amd64/13.0/desktop, gcc-4.7.3, glibc-2.16.0, 3.10.12-gentoo x86_64)
EMERGE_DEFAULT_OPTS="--quiet-build=y --with-bdeps=y"
# time emerge -pDuv --changed-use --keep-going @world
These are the packages that would be merged, in order:
Calculating dependencies... done!
Total: 0 packages, Size of downloads: 0 kB
real 7m32.192s
user 6m32.160s
sys 0m5.530s
Admittedly the machine was in light use at the time.
Still, one core is pinned at 100% for the duration.
Running with python 2.7 or python 3.2 makes no difference.
I've been trying to get a profiled run of that, the current attempt just finished while I was writing this.
> 354839501 function calls (352767719 primitive calls) in 3265.769 seconds
Yikes.
I just realized that I don't know how to read the results, will attach shortly.
Created attachment 359430 [details]
Sorted profiling output
Generated by
#!/usr/bin/env python3
import pstats
p = pstats.Stats('emerge_pworld_pyprofile.txt')
p.strip_dirs().sort_stats('cumulative').print_stats()
Created attachment 359432 [details]
Raw profiling data used for previous attachent
Generated by
# /usr/lib64/python3.2/profile.py -o emerge_pworld_pyprofile.txt /usr/bin/emerge -pDuv --changed-use --keep-going @world
Running took almost 2 hours.
Now I get around 2min in place of 3-4 min. It's quite better and almost bearable. This might be fixed/improved by the path in bug 486580. emerge is also too slow on my ~amd64 gentoo system with 8GB of memory and a i7-2630QM CPU: # time emerge -auvDt --keep-going @system @world These are the packages that would be merged, in reverse order: Calculating dependencies... done! [...] real 7m42.912s user 7m35.669s sys 0m6.751s Did you test with portage-9999? Things have changed substantially since then. |
