Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 79603 - portage-2.0.51-r15 takes an incredibly long time to emerge
Summary: portage-2.0.51-r15 takes an incredibly long time to emerge
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: New packages (show other bugs)
Hardware: x86 Linux
: High minor (vote)
Assignee: Portage team
Depends on:
Reported: 2005-01-26 10:01 UTC by John Altstadt
Modified: 2005-05-05 07:10 UTC (History)
0 users

See Also:
Package list:
Runtime testing required: ---


Note You need to log in before you can comment on or make changes to this bug.
Description John Altstadt 2005-01-26 10:01:27 UTC
portage-2.0.51-r15 takes so long to emerge that it looks like the process has hung and may cause people to kill it. It progresses through the normal sort of emerge messages then prints out:
 * Compiling python modules...
and doesn't do anything else for half an hour. This happens exactly the same for two different systems. I first saw this with 2.0.51-r14.

Note, this isn't really a bug report, just a report that something weird is going on.

Reproducible: Always
Steps to Reproduce:
1. emerge -v portage
2. wait

Actual Results:  
The log file shows:
1106758608: Started emerge on: Jan 26, 2005 08:56:48
1106758608:  *** emerge --verbose portage
1106758609:  >>> emerge (1 of 1) sys-apps/portage-2.0.51-r15 to /
1106758609:  === (1 of 1) Cleaning
1106758610:  === (1 of 1) Compiling/Merging
1106760704:  === (1 of 1) Post-Build Cleaning
1106760720:  >>> AUTOCLEAN: sys-apps/portage
1106760725: === Unmerging... (sys-apps/portage-2.0.51-r14)
1106760751:  >>> unmerge success: sys-apps/portage-2.0.51-r14
1106760753:  ::: completed emerge (1 of 1) sys-apps/portage-2.0.51-r15 to /
1106760753:  *** Finished. Cleaning up...
1106760761:  *** exiting successfully.
1106760762:  *** terminating.

That is almost 36 minutes!

While it is sitting in the "Compiling python modules" state, top shows that
there is no CPU or memory being consumed, but the system is very sluggish. It
almost acts I/O bound, but there was no disk activity at the time either. The
load average was quite high though, around 3.

Expected Results:  
It should have used up lots of CPU and/or memory and/or disk I/O, and completed
the emerge quickly.

sabre root # emerge info
Portage 2.0.51-r15 (default-linux/x86/2004.3, gcc-3.3.5,
glibc-, 2.4.28-gentoo-r5 i686)
System uname: 2.4.28-gentoo-r5 i686 AMD Athlon(tm) XP 1700+
Gentoo Base System version 1.4.16
Python:              dev-lang/python-2.2.3-r5,dev-lang/python-2.3.4 [2.3.4 (#1,
Dec 22 2004, 15:42:46)]
distcc 2.16 i686-pc-linux-gnu (protocols 1 and 2) (default port 3632) [enabled]
ccache version 2.3 [enabled]
dev-lang/python:     2.2.3-r5, 2.3.4
sys-devel/autoconf:  2.59-r5
sys-devel/automake:  1.8.5-r1
sys-devel/libtool:   1.5.2-r7
virtual/os-headers:  2.4.21-r1
CFLAGS="-O3 -march=athlon-xp -funroll-loops -pipe"
CONFIG_PROTECT="/etc /usr/X11R6/lib/X11/xkb /usr/kde/2/share/config
/usr/kde/3.1/share/config /usr/kde/3.2/share/config /usr/kde/3.3/env
/usr/kde/3.3/share/config /usr/kde/3.3/shutdown /usr/kde/3/share/config
/usr/lib/mozilla/defaults/pref /usr/share/config
/usr/share/texmf/dvipdfm/config/ /usr/share/texmf/dvips/config/
/usr/share/texmf/tex/generic/config/ /usr/share/texmf/tex/platex/config/
/usr/share/texmf/xdvi/ /var/qmail/control"
CONFIG_PROTECT_MASK="/etc/gconf /etc/terminfo /etc/env.d"
CXXFLAGS="-O3 -march=athlon-xp -funroll-loops -pipe"
FEATURES="autoaddcvs autoconfig ccache distcc distlocks sandbox severe sfperms
strict userpriv"
USE="x86 3dnow X alsa apache2 apm arts artswrappersuid avi berkdb bitmap-fonts
bonobo cdr cjk crypt cups curl dga directfb divx4linux doc dvb dvd dvdread emacs
encode esd ethereal f77 fam fastcgi fbcon flac font-server foomaticdb fortran gb
gd gdbm gif gnome gphoto2 gpm gtk gtk2 gtkhtml guile imagemagick imap imlib
innodb ipv6 java jpeg junit kde libg++ libwww live mad maildir mailwrapper
mikmod mmx motif mozilla mpeg mysql nas ncurses network nls odbc ofx oggvorbis
opengl oss pam pda pdflib perl png python qt quicktime quotes readline ruby
samba sasl sdl slang slp spell sse ssl svga tcltk tcpd tetex theora tiff
truetype truetype-fonts type1-fonts unicode usb wmf xml xml2 xmms xv xvid zeo zlib"

sabre root #
Comment 1 Nicholas Jones (RETIRED) gentoo-dev 2005-01-31 16:04:27 UTC
Did you check your dmesg? Make sure there weren't disk errors.

That part does use a lot of IO.
Comment 2 John Altstadt 2005-01-31 17:23:46 UTC
I just reran this emerge and checked in on top every once in a while.

It appears that the main action that happens during the "Compiling python modules..." phase is that chown runs for about 5-10 minutes and then chmod runs for another 20-25 minutes. During that time:

- there were no seek noises from my hard drives
- nothing was added to dmesg
- the only syslogs were recording cron jobs launching every 10 minutes
- top said that the CPU was 97% idle typically
- when chown was running, top said it consumed 1-4% of the CPU with a load average around 1.1
- when chmod was running, top said it consumed 0-4% of the CPU with a load average around 2.8
- the last time I saw chmod running, it had consumed about 8.5 CPU seconds over 20+ minutes of wall clock time
- top usually consumed the most CPU at around 2% the whole time

time emerge portage returned with
real    33m32.747s
user    0m24.300s
sys     0m17.990s

I'm running with reiser 3. Perhaps there are issues with changing file ownership and permissions with reiser, but I haven't noticed that any bulk chown or chmod commands took a long time before.

I will try again with strace.
Comment 3 John Altstadt 2005-01-31 17:34:21 UTC
As expected, strace shows a fork and wait on, and then the strace output stops during the "Compiling python modules..." phase.

Oh well. Short of hooking up gdb, I'm not going to be able to give you any more info.

Curious that chown and chmod don't want to execute in a timely fashion.
Comment 4 Nicholas Jones (RETIRED) gentoo-dev 2005-02-28 08:32:17 UTC
Did you ever resolve this issue?

Did you try running chown and chmod yourself?
Comment 5 John Altstadt 2005-02-28 10:38:08 UTC
No, this was never resolved.

It looks like the recursive chown/chmod of /var/tmp/ccache (in the pkg_postinst section of the ebuild) takes an absurd amount of time to run. While it is running, it doesn't look like any CPU or I/O is being used. It would be interesting to find out if it acts the same way with other filesystems.
Comment 6 John Altstadt 2005-02-28 10:45:11 UTC
I ran the chown command from the ebuild manually to get the info above.
Comment 7 Jason Stubbs (RETIRED) gentoo-dev 2005-05-04 08:16:00 UTC
The ebuild no longer does these chowns. However, they do occur in portage itself. They should only ever happen when changing FEATURES="userpriv" on and off, however.
Comment 8 John Altstadt 2005-05-05 06:55:03 UTC
I just emerged portage- It took less than a minute. This is a massive improvement.

Is there any sort of "go get a coffee" message printed by portage when it determines that it needs to run the chown/chmod?
Comment 9 John Altstadt 2005-05-05 06:56:16 UTC
I just emerged portage- It took less than a minute. This is a massive improvement.

Is there any sort of "go get a coffee" message printed by portage when it determines that it needs to run the chown/chmod?
Comment 10 Jason Stubbs (RETIRED) gentoo-dev 2005-05-05 07:10:39 UTC
Actually, nothing is printed. I should probably add that.