Bug 553546 – net-proxy/http-replicator-{3.0-r4,4.0_alpha2-r4} high cpu usage limits donwload speed (python read() on xfs abuse cpu)

• Product: Gentoo Linux
• Status: RESOLVED NEEDINFO

[Description Marcin Mirosław 2015-06-29 12:44:37 UTC]

I can't download from http-replicator with speed more than ~1.3MB/s due to very high cpu usage by http-replicator. Below is example when I'm trying to download file on the same machine that runs http-replicator:

# time sudo -u portage /usr/bin/python2.7 /usr/bin/http-replicator -s -f --pid /var/run/http-replicator.pid  --dir /data/distfiles_cache/ --user portage --alias /usr/portage/packages/All:All --log /var/log/http-replicator.log --ip 192.168.*.* --port 8080
INFO: HttpReplicator started
STAT: HttpClient 1 bound to 192.168.1.230
INFO: HttpClient 1 proxy request for http://distfiles.gentoo.org/distfiles/gcc-4.8.4.tar.bz2
INFO: HttpServer 1 serving file from cache
STAT: HttpClient 1 received 86220648 bytes
^CINFO: HttpReplicator terminated

real    1m36.758s
user    0m0.160s
sys     1m0.080s


$ http_proxy="192.168.1.230:8080" wget -O /dev/null http://distfiles.gentoo.org/distfiles/gcc-4.8.4.tar.bz2 
--2015-06-29 14:31:36--  http://distfiles.gentoo.org/distfiles/gcc-4.8.4.tar.bz2
Connecting to 192.168.1.230:8080... connected.
Proxy request sent, awaiting response... 200 OK
Length: 86220648 (82M)
Saving to: ‘/dev/null’

/dev/null                                 100%[=====================================================================================>]  82.23M  1.38MB/s   in 60s    

2015-06-29 14:32:36 (1.37 MB/s) - ‘/dev/null’ saved [86220648/86220648]
    

When I download from couple clients summary speed is about 1.3MB/s
Interesting thing is that high cpu usage is not in user space but in kernel thread (sys). I run http-replicator with strace -c and it looks that read taks so many time:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
INFO: HttpReplicator terminated
 99.98   63.956571       29405      2175           read
  0.02    0.010000         119        84           munmap
  0.00    0.000292           0      1959           sendto
  0.00    0.000026           0      1876           select
  0.00    0.000013           0      3967           lseek
  0.00    0.000000           0        76           write
  0.00    0.000000           0       620       444 open
  0.00    0.000000           0       191           close
  0.00    0.000000           0       275       184 stat
  0.00    0.000000           0      2230           fstat
  0.00    0.000000           0        51        45 lstat
  0.00    0.000000           0       155           mmap


WHen I moved cache from xfs (on raid6) to reiserfs (on raid1) I had speed 1.02 GB/s. So this is something how python interracts with XFS. And so it's more interresting this file should be in OS cache so read() shouldn't touch md.


Reproducible: Always




# emerge --info
Portage 2.2.18 (python 3.3.5-final-0, default/linux/amd64/13.0, gcc-4.8.4, glibc-2.20-r2, 3.17.7-gentoo x86_64)
=================================================================
System uname: Linux-3.17.7-gentoo-x86_64-Intel-R-_Core-TM-2_Quad_CPU_Q9400_@_2.66GHz-with-gentoo-2.2
KiB Mem:     8094368 total,   2582040 free
KiB Swap:    2097148 total,   1320608 free
Timestamp of repository gentoo: Mon, 29 Jun 2015 12:00:01 +0000
sh bash 4.3_p33-r2
ld GNU gold (Gentoo 2.24 p1.4 2.24) 1.11
app-shells/bash:          4.3_p33-r2::gentoo
dev-lang/perl:            5.20.2::gentoo
dev-lang/python:          2.7.9-r1::gentoo, 3.3.5-r1::gentoo, 3.4.1::gentoo
dev-util/cmake:           3.2.2::gentoo
dev-util/pkgconfig:       0.28-r2::gentoo
sys-apps/baselayout:      2.2::gentoo
sys-apps/openrc:          0.16.4::gentoo
sys-apps/sandbox:         2.6-r1::gentoo
sys-devel/autoconf:       2.69::gentoo
sys-devel/automake:       1.13.4::gentoo, 1.14.1::gentoo
sys-devel/binutils:       2.24-r3::gentoo
sys-devel/gcc:            4.8.4::gentoo
sys-devel/gcc-config:     1.7.3::gentoo
sys-devel/libtool:        2.4.6::gentoo
sys-devel/make:           4.1-r1::gentoo
sys-kernel/linux-headers: 3.18::gentoo (virtual/os-headers)
sys-libs/glibc:           2.20-r2::gentoo
Repositories:

gentoo
    location: /usr/portage
    sync-type: rsync
    sync-uri: rsync://rsync.gentoo.org/gentoo-portage
    priority: -1000

Installed sets: @cacti
ACCEPT_KEYWORDS="amd64"
ACCEPT_LICENSE="* -@EULA dlj-1.1"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -pipe -march=native -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php5.6/ext-active/ /etc/php/cgi-php5.6/ext-active/ /etc/php/cli-php5.6/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo"
CXXFLAGS="-O2 -pipe -march=native -pipe"
DISTDIR="/usr/portage/distfiles"
FCFLAGS="-O2 -pipe"
FEATURES="assume-digests binpkg-logs cgroup collision-protect config-protect-if-modified distlocks ebuild-locks fixlafiles news parallel-fetch preserve-libs protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://distfiles.gentoo.org"
LANG="en_US.utf8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
MAKEOPTS="-j4 -l 5"
PKGDIR="/usr/portage/packages"
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_EXTRA_OPTS="-O"
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"
PORTAGE_TMPDIR="/var/tmp"
USE="acl amd64 bash-completion bzip2 caps cli cracklib crypt cxx device-mapper dri glibc-omitfp hpn iconv iproute2 logrotate mmap mmx mmxext modules multilib ncurses network-cron nls nptl openmp pam pcre readline session slang snmp sse sse2 sse3 ssl ssse3 threads threadsafe unicode urandom vhosts vim vim-pager vim-syntax xattr zlib" ABI_X86="64" 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="actions alias auth_basic auth_digest authn_anon authn_dbd authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache dav dav_fs dav_lock dbd deflate dir disk_cache env expires ext_filter file_cache filter headers ident imagemap include info log_config logio mem_cache mime mime_magic negotiation proxy proxy_ajp proxy_balancer proxy_connect proxy_http rewrite setenvif so speling status unique_id userdir usertrack vhost_alias" APACHE2_MPMS="prefork" 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" CPU_FLAGS_X86="mmxext sse2 sse3 ssse3" 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 ublox ubx" INPUT_DEVICES="keyboard mouse evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LINGUAS="pl en" OFFICE_IMPLEMENTATION="libreoffice" PYTHON_SINGLE_TARGET="python2_7" PYTHON_TARGETS="python2_7 python3_3" RUBY_TARGETS="ruby19 ruby20" USERLAND="GNU" VIDEO_CARDS="fbdev glint intel mach64 mga nouveau nv r128 radeon savage sis tdfx trident vesa via vmware dummy v4l" 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"
USE_PYTHON="3.3 2.7"
Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, INSTALL_MASK, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS

[Comment 1 Pacho Ramos 2016-08-12 13:42:59 UTC]

is this still happening to you with a more recent kernel? (and likely fixed XFS support)