Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 722518 - sys-apps/portage: emerge dependency calculation takes a long time while strace shows many repeating poll and recvmsg calls
Summary: sys-apps/portage: emerge dependency calculation takes a long time while strac...
Status: RESOLVED NEEDINFO
Alias: None
Product: Portage Development
Classification: Unclassified
Component: Core (show other bugs)
Hardware: All Linux
: Normal normal (vote)
Assignee: Portage team
URL:
Whiteboard:
Keywords:
Depends on:
Blocks: 835380
  Show dependency tree
 
Reported: 2020-05-11 17:28 UTC by Joakim Tjernlund
Modified: 2023-05-20 07:48 UTC (History)
2 users (show)

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


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Joakim Tjernlund 2020-05-11 17:28:34 UTC
I have noticed (for a long time now) that emerge -aNDuv world can take several
minutes to complete on a fast development computer(with NVMe disk). When I strace emerge I see it stuck in some loop:

[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="U\2\352\0\313\215\263|\3\4\4\0\0\0\0\0\0\0\0\4\4\4\4\4\0\0\3\37%\2\0\0", iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 2, 0) = 0 (Timeout)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 26305] recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
.....
Comment 1 Sam James archtester Gentoo Infrastructure gentoo-dev Security 2020-05-11 17:30:45 UTC
Please include emerge --info for completeness.
Comment 2 Joakim Tjernlund 2020-05-11 17:33:37 UTC
emerge --info
Portage 2.3.99 (python 3.6.10-final-0, default/linux/amd64/17.0/desktop, gcc-8.4.0, glibc-2.30-r8, 4.19.114-x86_64 x86_64)
=================================================================
System uname: Linux-4.19.114-x86_64-x86_64-Intel-R-_Core-TM-_i7-6700_CPU_@_3.40GHz-with-gentoo-64
KiB Mem:    24090596 total,   4520764 free
KiB Swap:    8388604 total,   8387324 free
Timestamp of repository gentoo: Mon, 11 May 2020 15:45:01 +0000
Head commit of repository gentoo: 2ccaf59d085aa5301d2989cae8e8914003f57789
sh bash 5.0_p17
ld GNU ld (Gentoo 2.33.1 p2) 2.33.1
distcc 3.3.3 x86_64-pc-linux-gnu [disabled]
ccache version 3.7.7 [disabled]
app-shells/bash:          5.0_p17::gentoo
dev-java/java-config:     2.2.0-r4::gentoo
dev-lang/perl:            5.30.1::gentoo
dev-lang/python:          2.7.18::gentoo, 3.6.10-r2::gentoo
dev-util/ccache:          3.7.7-r1::gentoo
dev-util/cmake:           3.16.5::gentoo
dev-util/pkgconfig:       0.29.2::gentoo
sys-apps/baselayout:      2.6-r1::gentoo
sys-apps/openrc:          0.42.1::gentoo
sys-apps/sandbox:         2.13::gentoo
sys-devel/autoconf:       2.13-r1::gentoo, 2.69-r4::gentoo
sys-devel/automake:       1.15.1-r2::gentoo, 1.16.1-r1::gentoo
sys-devel/binutils:       2.33.1-r1::gentoo
sys-devel/gcc:            8.4.0::gentoo
sys-devel/gcc-config:     2.2.1::gentoo
sys-devel/libtool:        2.4.6-r6::gentoo
sys-devel/make:           4.2.1-r4::gentoo
sys-kernel/linux-headers: 4.19::gentoo (virtual/os-headers)
sys-libs/glibc:           2.30-r8::gentoo
Repositories:

tmv3-cross-overlay
    location: /var/lib/layman/tmv3-cross-overlay
    sync-type: laymansync
    sync-uri: git://git.transmode.se/tmv3-cross-overlay.git
    priority: 50

gentoo
    location: /usr/portage
    sync-type: rsync
    sync-uri: rsync://devsrv.transmode.se/portage
    priority: 100
    sync-rsync-verify-max-age: 24
    sync-rsync-verify-jobs: 1
    sync-rsync-verify-metamanifest: no
    sync-rsync-extra-opts: 

transmode
    location: /var/lib/layman/transmode
    sync-type: laymansync
    sync-uri: https://devsrv.transmode.se/svn/portage-overlay/stable
    masters: gentoo
    priority: 150

Installed sets: @cross-powerpc-toolchains, @i3, @infinera-desktop, @infinera-plasma, @xmonad
ACCEPT_KEYWORDS="amd64"
ACCEPT_LICENSE="* -@EULA FraunhoferFDK ms-teams-pre dlj-1.1 Oracle-BCLA-JavaSE AdobeFlash-11.x google-chrome"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/lib64/libreoffice/program/sofficerc /usr/share/config /usr/share/gnupg/qualified.txt /usr/share/maven-bin-3.6/conf /usr/share/sddm/scripts/Xsession"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/openconnect/csd-wrapper.sh /etc/php/apache2-php7.4/ext-active/ /etc/php/cgi-php7.4/ext-active/ /etc/php/cli-php7.4/ext-active/ /etc/portage/package.keywords/zzzautounmask /etc/portage/package.unmask/zzzautounmask /etc/portage/package.use/zzzautounmask /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c /usr/share/dbus-1/services/org.kde.plasma.Notifications.service"
CXXFLAGS="-O2 -pipe"
DISTDIR="/usr/portage/distfiles"
EMERGE_DEFAULT_OPTS="--verbose-conflicts --autounmask-write --autounmask  --autounmask-continue --ignore-soname-deps=n --quiet --jobs=4 --keep-going --load-average=12 --with-bdeps=y --usepkg --usepkg-exclude 'sys-firmware/hpuefi-mod app-emulation/virtualbox-modules app-emulation/virtualbox-guest-additions'"
ENV_UNSET="DBUS_SESSION_BUS_ADDRESS DISPLAY GOBIN PERL5LIB PERL5OPT PERLPREFIX PERL_CORE PERL_MB_OPT PERL_MM_OPT XAUTHORITY XDG_CACHE_HOME XDG_CONFIG_HOME XDG_DATA_HOME XDG_RUNTIME_DIR"
FCFLAGS="-O2 -pipe"
FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs config-protect-if-modified distlocks ebuild-locks fixlafiles ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch pkgdir-index-trusted preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://devsrv.transmode.se/portage http://devsrv.transmode.se/portage/local http://ftp.df.lth.se/pub/gentoo"
INSTALL_MASK=" /usr/share/dbus-1/services/org.kde.plasma.Notifications.service  /usr/lib64/libnssckbi.so /usr/lib/libnssckbi.so  /usr/lib64/pkcs11/gnome-keyring-pkcs11.so /usr/lib/pkcs11/gnome-keyring-pkcs11.so "
LANG="en_GB.UTF-8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
LINGUAS="en sv en_GB sv_SE en_US"
MAKEOPTS="-s -j8"
PKGDIR="/usr/portage/packages"
PORTAGE_BINHOST="http://devsrv.transmode.se/portage/packages/gentoo64/"
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages --exclude=/.git"
PORTAGE_TMPDIR="/var/tmp"
USE="X a52 aac accessibility acl acpi ads alsa amd64 bash-completion berkdb bluetooth branding bzip2 cairo caja cdda cdr clang cli client crypt cscope cups cxx dbus device-mapper dhcpcd dri dri3 dts dvd dvdr elogind emacs emboss encode exif faac ffmpeg flac fontconfig fortran gbm gdbm gif glamor gles gles2 glib gold gpm gssapi gstreamer gtk gtk3 hwaccel iconv icu idn introspection ipv6 java jpeg kerberos kvm lcms ldap libnotify libtirpc lvm mad mate mmx mng modemmanager mp3 mp4 mpeg mtp multilib natspec ncurses networkmanager nls nptl nscd ogg opengl openmp openssl opus p2p pam pango pcre pdf pdfimport pidgin pm-utils png policykit postproc ppds pulseaudio python qemu qt5 readline resolvconf rpc samba sasl script sdl seccomp secure-delete smi smp sound spell spice split-usr sqlite srt sse sse2 sse3 sse4 sse4_1 ssl ssse3 startup-notification subversion svg sync-plugin-portage system-bootstrap system-cairo system-harfbuzz system-icu system-jpeg system-libvpx system-llvm system-sqlite tcpd threads tiff truetype udev udisks unicode upower usb usbredir v4l vaapi vala vdpau vim virt-network virtualbox vnc vorbis vpx vulkan wayland webdav wxwidgets x264 xattr xcb xft xinerama xml xpm xv xvid zlib" ABI_X86="64" ADA_TARGET="gnat_2018" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" 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="karbon sheets words" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="aes avx f16c mmx mmxext pclmul popcnt sse sse2 sse3 sse4_1 sse4_2 ssse3" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock greis isync itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf skytraq superstar2 timing tsip tripmate tnt ublox ubx" GRUB_PLATFORMS="efi-64 pc qemu" INPUT_DEVICES="evdev libinput synaptics" KERNEL="linux" L10N="en sv en-GB sv-SE en-US" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php5-5" POSTGRES_TARGETS="postgres10 postgres11" PYTHON_SINGLE_TARGET="python3_6" PYTHON_TARGETS="python2_7 python3_6" QEMU_SOFTMMU_TARGETS="i386 x86_64 ppc arm" QEMU_USER_TARGETS="i386 x86_64 ppc arm" RUBY_TARGETS="ruby24 ruby25" USERLAND="GNU" VIDEO_CARDS="intel i965 amdgpu vmware qxl fbdev vesa cirrus" 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:  CC, CPPFLAGS, CTARGET, CXX, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Comment 3 Jonas Stein gentoo-dev 2020-05-14 12:45:17 UTC
I suggest you discuss this on IRC #gentoo-portage and add a summary of the outcome here, because the bugtracker is not good for discussions.
Comment 4 Zac Medico gentoo-dev 2020-05-14 17:27:12 UTC
It's unusual to see the poll calls, since portage's event loop normally uses epoll_wait. For example, this results in an epoll_wait call for me:

$ python
Python 3.6.10 (default, Apr  4 2020, 11:16:01) 
[GCC 9.2.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import portage
>>> from portage.util.futures import asyncio
>>> loop = asyncio.get_event_loop()
>>> future = loop.create_future()
>>> loop.run_until_complete(future)

Does this result in an epoll_wait call for you, or not?
Comment 5 Joakim Tjernlund 2020-05-14 17:36:54 UTC
strace -f -p 23827 
....

pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "f", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "u", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "t", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "u", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "r", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "e", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 1 (in [0], left {tv_sec=0, tv_usec=0})
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, ")", 1)                         = 1
select(1, [0], NULL, [0], {tv_sec=0, tv_usec=0}) = 0 (Timeout)
write(1, "loop.run_until_complete(future)", 31) = 31
rt_sigaction(SIGWINCH, {sa_handler=0x7f9f5dbf55c0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f9f5d8f0420}, {sa_handler=0x7f9f5cefee30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9f5d8f0420}, 8) = 0
select(1, [0], NULL, NULL, NULL)        = 1 (in [0])
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigaction(SIGWINCH, {sa_handler=0x7f9f5cefee30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9f5d8f0420}, {sa_handler=0x7f9f5dbf55c0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f9f5d8f0420}, 8) = 0
pselect6(1, [0], NULL, NULL, NULL, {[], 8}) = 1 (in [0])
read(0, "\r", 1)                        = 1
write(1, "\n", 1)                       = 1
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
rt_sigaction(SIGWINCH, {sa_handler=0x7f9f5dbf55c0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f9f5d8f0420}, {sa_handler=0x7f9f5cefee30, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9f5d8f0420}, 8) = 0
getpid()                                = 23827
epoll_wait(3,

long pause here, minutes and no CPU load, it is just waiting.
Comment 6 Zac Medico gentoo-dev 2020-05-14 17:49:40 UTC
(In reply to Joakim Tjernlund from comment #5)
> epoll_wait(3,
> 
> long pause here, minutes and no CPU load, it is just waiting.

This test case is supposed to have forever in epoll_wait, so this is the expected result.

So, we need to find out what is causing the poll and recvmsg calls. When it's doing that, send the process a SIGUSR1 signal which will give you a pdb prompt, then type bt (for backtrace) and press Enter.