Very slow linux download speed, excessive disk and cpu usage

[ghost]

https://github.com/spring/pr-downloader/blob/master/src/Downloader/Rapid/Sdp.cpp#L197-L205

This closes each downloaded file, then reopens/rereads and checks md5:

pr-downloader/src/FileSystem/FileSystem.cpp

Lines 48 to 54 in 5397db3

	bool CFileSystem::fileIsValid(const FileData* mod, const std::string& filename) const
	{
	HashMD5 md5hash;
	int bytes;
	unsigned char data[IO_BUF_SIZE];
	FILE* f= propen(filename.c_str(), "rb");
	gzFile inFile = gzdopen (fileno(f), "rb");

Since the curl write calls are sequential:

pr-downloader/src/Downloader/Rapid/Sdp.cpp

Line 276 in 5498204

curl_easy_setopt(curlw->GetHandle(), CURLOPT_WRITEFUNCTION, write_streamed_data);

... this blocks the download loop until each file is opened, written to, closed, re-opened, loaded in a gzip file object, md5 checked and closed again.

There are much better/faster ways to check the files in-memory, during streamer download, by chunks, using gzip, md5 and crc objects - crc might be the fastest and the sdp provides such data, python example (though thoroughly untested early code that's really unstable):

https://github.com/serg9/rapid_nonet/blob/master/receive_loop.py#L118-L146

There's only one file close, no-rereading the file from disk, using zlib.decompressobj and binascii.crc32, they are meant for on-the-fly stream decompression, there have to be c++ ways to do it too.

Memory usage is not a problem since each received chunk fits comfortably in RAM. I don't know if I have some disk issues or it's my current fstab setup, but the current version of pr-downloader is using my disk to 100% and the download speed is ~100-500kbps max (since it waits for disk). In-ram decompression+crc check is substantially faster on my machine.

For me, this makes it unusable under Linux, might also be related to how disk caching is handled, but I didn't look into that because python kind of handles that on its own.

I can't replicate the crash I told you about now but I'll keep trying.

If not enough linux users get this, it should be marked low priority (I have special mounts).

strace http://pastebin.com/f0HEJ1X6
with time of the day http://pastebin.com/dV6070GX , this makes the sluggishness obvious.

[abma]

a "cold start" here:

$ time pr-downloader ba:stable
...
real 0m27.141s
user 0m2.196s
sys 0m1.140s

with a debug build of pr-downloader (which outputs to console A LOT) to a normal hard-drive (no ssd).

thats 1,37MB/s (i've a 16MBit connection, ~1.6MB is the max speed).

i agree that i/o can be heavily optimized, but i don't have this issue. Is your harddisk maybe broken or starting to die?

[abma]

If not enough linux users get this, it should be marked low priority (I have special mounts).

what params do you use to mount the disk where pr-downloader stores its files? (usally ~/.spring/)

also side note: safety was chosen over speed: currently when pr-downloader crashes / is killed it shouldn't leave broken files on disk which are read/used by spring. (with some enhancements, the same can be accomplished with insane speed :) )

very likely the cause of the speed drop is fsync()...

[ghost]

Hi,

I'll test this on multiple drives, it's the only program that's giving me headaches on this disk though.
Each fsync call takes ~0.10 seconds judging from that strace, that's a minute and a half for each thousand files extra, but there's something else at play, since:

Latest Ubuntu:

$ time ./pr-downloader ba:stable
pr-downloader 0.7-208-g690d0e2
[Info] Using filesystem-writepath: /home/user/.spring
[Info] Found 19 repos in /home/user/.spring/rapid/repos.springrts.com/repos.gz
[Info] opened /home/user/.spring/rapid/packages.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/s44.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/swiw.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/evo.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/zk.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/techa.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jauria.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/chiliui.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/lups.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/modelshaders.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jw.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/tard.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/i18n.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jrtsc.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/feature-placer.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/spring-features.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/mcl.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/area17.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/devgame.repo.springrts.com/versions.gz
[Progress] 0% [ ] 0/0
[Download] Balanced Annihilation V9.06
[Info] opened /home/user/.spring/packages/76a5494d0fcac5cc512c0f98a30cc0a5.sdp.tmp
[Progress] 0% [ ] 0/0
[Info] Using rapid
[Info] http://packages.springrts.com/streamer.cgi?76a5494d0fcac5cc512c0f98a30cc0a5
[Progress] 100% [==============================] 25637824/25637824
[Info] Download complete!

real 6m36.453s
user 0m1.532s
sys 0m0.976s

That's clearly waiting on IO (and the network is just fine)

Gentoo in chroot:

time ./pr-downloader ba:stable
pr-downloader 0.7-208-g690d0e2
[Info] Using filesystem-writepath: /home/user/.spring
[Info] opened /home/user/.spring/rapid/repos.springrts.com/repos.gz
[Progress] 100% [==============================] 229/229
[Info] Found 19 repos in /home/user/.spring/rapid/repos.springrts.com/repos.gz
[Info] opened /home/user/.spring/rapid/packages.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/s44.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/swiw.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/evo.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/zk.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/techa.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jauria.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/chiliui.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/lups.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/modelshaders.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jw.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/tard.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/i18n.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/jrtsc.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/feature-placer.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/spring-features.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/mcl.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/area17.repo.springrts.com/versions.gz
[Info] opened /home/user/.spring/rapid/devgame.repo.springrts.com/versions.gz
[Progress] 100% [==============================] 48952/48952 1
[Download] Balanced Annihilation V9.06
[Info] opened /home/user/.spring/packages/76a5494d0fcac5cc512c0f98a30cc0a5.sdp.tmp
[Progress] 100% [==============================] 122787/122787
[Info] Using rapid
[Info] http://packages.springrts.com/streamer.cgi?76a5494d0fcac5cc512c0f98a30cc0a5
[Progress] 100% [==============================] 25637824/25637824
[Info] Download complete!

real 1m50.288s
user 0m1.716s
sys 0m0.788s

It still crunches the disk/cpu, but it's considerably better.

The setup I have could force most syncs to be "real" disk syncs so that's one thing, I need to change kernels to figure out what's going on because I didn't expect it to be that much lower on gentoo.

With the in-memory check and no syncs on python, download time is pretty much limited to bandwidth, so I'm getting < 10 seconds there, but this is too weird so I'll check kernel/SMART/sata settings.

[cleanrock]

Fyi, its fine on my archlinux system:
$ time ./src/pr-downloader --filesystem-writepath dl_dir ba:stable
pr-downloader 0.7-224-g313b6b9
[Download] Balanced Annihilation V9.07
real 0m16.855s
user 0m0.507s
sys 0m0.323s

[ghost]

Thanks for that, my best time so far was 1:50 on a different setup with another hdd (but this one isn't new either), even with noatime, either way it's much better than 6 minutes. I don't have new hdds to test this with and no ssd either.

strace -C -tt pr-downloader ba:stable 

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 86.37    0.088000          20      4317           fsync
  3.38    0.003447           0      9279           write
  2.78    0.002830           1      4452           rename
  2.70    0.002750           1      4369           munmap
  1.46    0.001483           0     13105      4338 close
  1.06    0.001077           0     10961           read
  1.04    0.001061           0      8722           open
  0.60    0.000614           0      4469           lseek
  0.25    0.000259           0      4407           fstat
  0.25    0.000253           0     15020     13438 stat
  0.05    0.000050           0      7671           rt_sigaction
  0.02    0.000025           0      4142           poll
  0.02    0.000024           0      4413           mmap
  0.01    0.000012           0      2006           recvfrom
  0.00    0.000000           0        32           mprotect
  0.00    0.000000           0        50           brk
  0.00    0.000000           0        22           rt_sigprocmask
  0.00    0.000000           0        44           ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0        62           select
  0.00    0.000000           0        44           alarm
  0.00    0.000000           0         1           getpid
  0.00    0.000000           0        45           socket
  0.00    0.000000           0        44        22 connect
  0.00    0.000000           0        22           sendto
  0.00    0.000000           0        22           getsockname
  0.00    0.000000           0        22           getpeername
  0.00    0.000000           0        22           getsockopt
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         2           uname
  0.00    0.000000           0        44           fcntl
  0.00    0.000000           0       280           mkdir
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0        22           sendmmsg
------ ----------- ----------- --------- --------- ----------------
100.00    0.101885                 98116     17799 total

[abma]

@serg9:

can you test this please?

mkdir -p /tmp/test && time pr-downloader --filesystem-writepath /tmp/test ba:stable && time rsync -a /tmp/test /tmp/test2

the fsync is/was there because when developing for several times i got 0 byte files.

[abma]

also, can you please provide your mount flags?

[ghost]

/dev/sda1 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)

Linux computer 3.19.0-26-generic #28-Ubuntu SMP Tue Aug 11 14:16:32 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
mkdir -p /tmp/test && time ./pr-downloader --filesystem-writepath /tmp/test ba:stable && time rsync -a /tmp/test /tmp/test2
pr-downloader 0.7-208-g690d0e2
...
[Download] Balanced Annihilation V9.07
[Info] http://packages.springrts.com/streamer.cgi?32f43f1a18d3efe18070b7b174429244
...

real 1m54.791s
user 0m1.624s
sys 0m0.908s

real 0m0.315s
user 0m0.212s
sys 0m0.212s

Interesting rsync data:

rsync -a rsync://ftp... (local fast gentoo portage mirror) .
-- get one from https://www.gentoo.org/support/rsync-mirrors/

real 0m53.743s
user 0m5.136s
sys 0m16.024s

rsync full portage dir from one drive to another:
(I think there's some caching involved here because it's too low)
real 0m26.400s
user 0m3.592s
sys 0m7.472s

and back again ...
real 0m50.820s
user 0m4.532s
sys 0m10.684s

total portage files
find | wc-l
183007

both drivers are:
relatime,errors=remount-ro,data=ordered
(I think it's default in Ubuntu)

Similar rsync numbers from:
Linux localhost 4.1.6-gentoo #3 SMP Wed Aug 26 18:01:32 EEST 2015 x86_64

back to pr-downloader/ubuntu, 4gb test partition, ba:stable:

• mkfs.vfat...

real 1m10.029s
user 0m1.860s
sys 0m1.172s

• mkfs.ext2...

default mount options

real 0m55.237s
user 0m1.872s
sys 0m0.692s

+noatime

real 1m2.008s
user 0m1.688s
sys 0m1.816s

• mkfs.ext3

real 2m11.110s
user 0m1.700s
sys 0m0.932s

+commit=120,noatime data=ordered

real 2m14.939s
user 0m1.704s
sys 0m1.036s

+noatime,data=writeback

real 1m38.727s
user 0m1.620s
sys 0m0.960s

• mkfs.ext4, default mount is relatime,data=ordered

real 1m58.384s
user 0m1.752s
sys 0m0.968s

noatime,data=writeback,commit=120

real 1m52.160s
user 0m1.748s
sys 0m0.816s

Git clones (but it looks like the network is the bottleneck here)

time git clone https://github.com/springlobby/springlobby
Cloning into 'springlobby'...
remote: Counting objects: 66539, done.
remote: Compressing objects: 100% (54/54), done.
remote: Total 66539 (delta 32), reused 0 (delta 0), pack-reused 66485
Receiving objects: 100% (66539/66539), 23.50 MiB | 128.00 KiB/s, done.
Resolving deltas: 100% (52032/52032), done.
Checking connectivity... done.

real 2m49.751s
user 0m5.768s
sys 0m1.832s

other drive
real 2m15.132s
user 0m5.460s
sys 0m1.432s