https download performance significantly worse in precise than lucid

[Scott Moser]

In Canonical's openstack installation, I noticed during publishing images that downloads on lucid seemed to occur faster than I could do the same download on precise.

$ wget https://cloud-images.ubuntu.com/precise/current/precise-server-cloudimg-amd64-disk1.img -O /dev/null

In the above, cloud-images.ubuntu.com is located very close to the instance running, such that on lucid I routinely get > 40M/s. However, on precise I routinely top out at 10M/s, with the highest I've ever seen at 19M/s. I once saw 49M/s on lucid.

very strangely (and thus making this harder to isolate), if I change 'https' above to 'http', both lucid and precise download in the 65-80M/S range.

Ie, https download is significantly slower in precise compared to lucid.

One likely unrelated point, in EC2, using the url
  https://ubuntu-data.s3.amazonaws.com/ebs/ubuntu-images/ubuntu-lucid-10.04-amd64-server-20100427.1.img.tar.gz
from a m1.large instance, lucid and precise are both getting in the 25-30M/s range. With the http url they both get in the 40M/s range.

Ie, there seems no real difference on EC2.

I do realize that this is difficult to isolate, and it is even possible that my results are affected by other guests on the same host or load on the http server at that time. However, the results have been very consistent over multiple days, over new instances.

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: linux-image-3.2.0-20-virtual 3.2.0-20.32
ProcVersionSignature: User Name 3.2.0-20.32-virtual 3.2.12
Uname: Linux 3.2.0-20-virtual x86_64
AplayDevices: Error: [Errno 2] No such file or directory
ApportVersion: 1.95-0ubuntu1
Architecture: amd64
ArecordDevices: Error: [Errno 2] No such file or directory
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
CRDA: Error: command ['iw', 'reg', 'get'] failed with exit code 1: nl80211 not found.
CurrentDmesg: [ 21.910968] init: plymouth-upstart-bridge main process (712) killed by TERM signal
Date: Fri Mar 23 19:29:54 2012
Ec2AMI: ami-00000000
Ec2AMIManifest: FIXME
Ec2AvailabilityZone: nova
Ec2InstanceType: m1.small
Ec2Kernel: unavailable
Ec2Ramdisk: unavailable
IwConfig:
 lo no wireless extensions.

 eth0 no wireless extensions.
MachineType: Bochs Bochs
PciMultimedia:

ProcEnviron:
 TERM=screen
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcFB:

ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.2.0-20-virtual root=UUID=bc55866c-8487-44b6-b0c7-56deac8b6a38 ro console=ttyS0
RfKill: Error: [Errno 2] No such file or directory
SourcePackage: linux
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 01/01/2007
dmi.bios.vendor: Bochs
dmi.bios.version: Bochs
dmi.chassis.type: 1
dmi.chassis.vendor: Bochs
dmi.modalias: dmi:bvnBochs:bvrBochs:bd01/01/2007:svnBochs:pnBochs:pvr:cvnBochs:ct1:cvr:
dmi.product.name: Bochs
dmi.sys.vendor: Bochs

[Joseph Salisbury (jsalisbury)]

Hi Scott,

Would it be possible for you to test the latest upstream kernel[0], to see if it also has this issue?

[0] http://kernel.ubuntu.com/~kernel-ppa/mainline/

[Joseph Salisbury (jsalisbury)]

Direct link to the latest mainline kernel:
http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.3-precise/

[Scott Moser (smoser)]

When I opened this bug, I didn't realize that the http traffic to that same url was roughly equivalent in precise and lucid. So, I thought that it must have been the virtio drivers that have regressed. However, realizing that, the likely issue would seem to be higher in the stack.

Doing another test, I actually get between 10 and 12M/S in both lucid and precise using curl, rather than wget.

This changes my suspicion to:
 * precise wget is regressed in performance between lucid and precise on https traffic.

As a result, for the moment I'm going to tag the kernel thread as invalid.

One point of data, in lucid, watching 'top' while the https is happening I see wget basically eating 90+% of one cpu. in precise that number is significantly lower, it only ends up getting to 50% or so.

Also, precise:
 $ time wget -q https://cloud-images.ubuntu.com/precise/current/precise-server-cloudimg-amd64-disk1.img -O /dev/null
 real 0m18.253s
 user 0m9.745s
 sys 0m1.796s

Lucid:
$ time wget -q https://cloud-images.ubuntu.com/precise/current/precise-server-cloudimg-amd64-disk1.img -O /dev/null
real 0m4.195s
user 0m3.110s
sys 0m0.590s

So, a significantly larger amount of time (3X) was spent in user precise wget compared to lucid.
The wget version in lucid is 1.12-1.1ubuntu2.1, in precise 1.13.4-2ubuntu1 .

I guess the next thing to do is to try precise wget on lucid or vice-versa and see what the difference is.

[Scott Moser (smoser)]

well,
  To see if the performance regression occurred just within wget and its string of dependencies, I did:
$ sudo sed -i.lucid s,lucid,precise, /etc/apt/sources.list
$ sudo apt-get update
$ sudo apt-get install wget
   # that pulled in libc-bin libc6 libgssapi-krb5-2 libk5crypto3 libkrb5-3 libkrb5support0 libnih-dbus1 libnih1 openssh-client openssh-server wget
   # then to get certificates I had to:
$ sudo apt-get install ca-certificates
   # which pulled in openssl.

After that, performance was in the 10-14M/s range. so there is definitely a performance hit in one of the packages listed above.

[Scott Moser (smoser)]

A simple build of precise's wget on lucid showed that wget itself isn't the problem (download did 50M/s) on lucid with rebuilt wget 1.13.4-2ubuntu1.

I also just now missed the new packages that were installed in the list above.
The 'apt-get install wget' of precises versions on lucid showed:
The following extra packages will be installed:
  krb5-locales libc-bin libc6 libgssapi-krb5-2 libk5crypto3 libkrb5-3 libkrb5support0 libnih-dbus1 libnih1 libssl1.0.0 multiarch-support openssh-client openssh-server

So that is a more complete list.

[Scott Moser (smoser)]

I pinged cjwatson today, and he pointed to bug 940230 , which may be releated.
However, a simple sniff of precise i386 instance (rather than amd64) did not perform much better than x86_64.

[cc (codecrumb)]

It would be helpful if you could isolate the cipher and protocol being used.

Try something from the client to the source like "openssl s_client -connect <SOURCE>:443 -tls1"

It should return the cipher that is being used.

As I commented on bug 940230, you should also test the relative speed of the cipher using "openssl speed <cipher>".

This should help isolate where the regression is.

Given that openssl affects so many packages, I think it's important that this be resolved asap as it'll have significant performance ramifications as evidenced by this bug.

[Serge Hallyn (serge-hallyn)]

These are both on a precise kernel. Lucid's is done from a lucid container.

openssl speed aes for lucid:
ubuntu@l1:~$ openssl speed aes
Doing aes-128 cbc for 3s on 16 size blocks: 15380506 aes-128 cbc's in 2.99s
Doing aes-128 cbc for 3s on 64 size blocks: 6040561 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 256 size blocks: 1769285 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 1024 size blocks: 461988 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 8192 size blocks: 58494 aes-128 cbc's in 2.99s
Doing aes-192 cbc for 3s on 16 size blocks: 14016534 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 64 size blocks: 5258845 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 256 size blocks: 1497092 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 1024 size blocks: 386960 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 8192 size blocks: 49032 aes-192 cbc's in 3.00s
Doing aes-256 cbc for 3s on 16 size blocks: 12884085 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 64 size blocks: 4656849 aes-256 cbc's in 2.99s
Doing aes-256 cbc for 3s on 256 size blocks: 1304574 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 1024 size blocks: 336883 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 8192 size blocks: 42429 aes-256 cbc's in 3.00s
OpenSSL 0.9.8k 25 Mar 2009
built on: Tue Jan 31 10:48:27 UTC 2012
options:bn(64,64) md2(int) rc4(ptr,char) des(idx,cisc,16,int) aes(partial) blowfish(ptr2)
compiler: cc -fPIC -DOPENSSL_PIC -DZLIB -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -m64 -DL_ENDIAN -DTERMIO -O3 -Wa,--noexecstack -g -Wall -DMD32_REG_T=int -DOPENSSL_BN_ASM_MONT -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM
available timing options: TIMES TIMEB HZ=100 [sysconf value]
timing function used: times
The 'numbers' are in 1000s of bytes per second processed.
type 16 bytes 64 bytes 256 bytes 1024 bytes 8192 bytes
aes-128 cbc 82303.71k 128865.30k 150978.99k 157691.90k 160261.82k
aes-192 cbc 74754.85k 112188.69k 127751.85k 132082.35k 133890.05k
aes-256 cbc 68715.12k 99678.37k 111323.65k 114989.40k 115859.46k

for precise:
serge@ubuntu:~$ openssl speed aes
Doing aes-128 cbc for 3s on 16 size blocks: 12626290 aes-128 cbc's in 2.99s
Doing aes-128 cbc for 3s on 64 size blocks: 3459936 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 256 size blocks: 886469 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 1024 size blocks: 463945 aes-128 cbc's in 3.00s
Doing aes-128 cbc for 3s on 8192 size blocks: 58903 aes-128 cbc's in 3.00s
Doing aes-192 cbc for 3s on 16 size blocks: 10715054 aes-192 cbc's in 2.99s
Doing aes-192 cbc for 3s on 64 size blocks: 2907217 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 256 size blocks: 738187 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 1024 size blocks: 393220 aes-192 cbc's in 3.00s
Doing aes-192 cbc for 3s on 8192 size blocks: 49715 aes-192 cbc's in 3.00s
Doing aes-256 cbc for 3s on 16 size blocks: 9308224 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 64 size blocks: 2477094 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 256 size blocks: 631263 aes-256 cbc's in 3.00s
Doing aes-256 cbc for 3s on 1024...

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Oibaf (oibaf)]

Can you still reproduce this issue on a newer and supported Ubuntu release?

[Launchpad Janitor (janitor)]

[Expired for openssl (Ubuntu) because there has been no activity for 60 days.]