resource-get is painfully slow

[Kevin W Monroe]

IBM has a few charms that require the user to provide resources before the charm can install. The resource for one of these charms [0] is about 200MB. It takes almost 40 minutes for the charm to fetch this resource from the controller:

...
2016-06-21 16:48:15 INFO juju-log IBM IM: fetching the ibm_im_installer resource
2016-06-21 17:24:52 INFO juju-log IBM IM: using /var/lib/juju/agents/unit-ibm-im-0/resources/ibm_im_installer/ibm_im_installer.zip as the ibm_im_installer resource
...

I ran some tests, and saw that the xfer rate between the controller and unit was a measly 80KB/s:

  root /var/lib/juju/tools/unit-ibm-im-0/jujud eth0 2.810 80.686 KB/sec

By contrast, a juju scp of the same 200MB resource from my laptop to the unit was 400KB/s:

  ubuntu sshd: ubuntu@pts/1 eth0 11.588 404.929 KB/sec

It doesn't seem right that i can xfer files to the unit from my laptop 5x faster than the controller. This test was done in Azure's South Central region with:

$ juju version
2.0-beta9-xenial-amd64

I'll run the numbers for AWS in just a few minutes. Please let me know what kind of data would be useful to have to triage this bug. I'm happy to fiddle with network/interface settings if needed.

[0] https://jujucharms.com/u/kwmonroe/ibm-im

[Kevin W Monroe (kwmonroe)]

AWS looks better. Same juju in aws/us-west-1 got the same 200MB resource downloaded in < 10 minutes, making it close to 400KB/s:

...
2016-06-21 18:11:02 INFO juju-log IBM IM: fetching the ibm_im_installer resource
2016-06-21 18:18:27 INFO juju-log IBM IM: using /var/lib/juju/agents/unit-ibm-im-0/resources/ibm_im_installer/ibm_im_installer.zip as the ibm_im_installer resource
...

While this is ok (certainly tolerable compared to azure), I think we can do much better. On AWS, I was able to put the controller's id_rsa.pub into a unit's ~/.ssh/authorized_keys file and scp this 200MB resource at 50MB/s. That's a crazy significant step up from 400KB/s.

IBM is about to drop *much* larger resources in their charms, which is why i'd like to try and get these speeds up. Their websphere resource is 2GB, which will make 400KB/s xfers painful, with 80KB/s xfers all but impossible.

[Kevin W Monroe (kwmonroe)]

I ran the scp test on azure... To summarize with normalized units (and apologies for not doing this in one shot):

Azure South Central
scp controller -> unit: 29 MB/s
resource-get unit <- controller: 0.08 MB/s

AWS US West 1
scp controller -> unit: 50 MB/s
resource-get unit <- controller: 0.4 MB/s

[James Tunnicliffe (dooferlad)]

Even uploading the resources takes ages and this seems to be because it is CPU limited on the server. This is very easy to recreate in LXD.

I am looking into this and hope to have some news soon.

[Cheryl Jennings (cherylj)]

Duplicate bug 1597354 has some additional logging if needed.

[James Tunnicliffe (dooferlad)]

It is also CPU limited on the client.

I can't find anything outside the go HTTP library that is taking such a long time. My guess is that there is a tiny buffer being used instead of something sensible, but I haven't found it yet.

It isn't our hashing code slowing us down. On an 800M file it takes a couple of seconds while the http client Do function is taking two minutes.

I am testing on LXD so there shouldn't be any limitation on network speed.

Reading the stream just next to the http post does so ~instantly.

[James Tunnicliffe (dooferlad)]

Looks like it is the go DES implementation being slow:

dooferlad@homework2 ~/dev/go/src/github.com/juju/juju $ go tool pprof $(which juju) /tmp/profile179913735/cpu.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
11.37s of 11.57s total (98.27%)
Dropped 23 nodes (cum <= 0.06s)
Showing top 10 nodes out of 30 (cum >= 11.22s)
      flat flat% sum% cum cum%
     7.86s 67.93% 67.93% 9.95s 86.00% crypto/des.feistel
     2.09s 18.06% 86.00% 2.09s 18.06% crypto/des.expandBlock
     0.71s 6.14% 92.13% 11s 95.07% crypto/des.cryptBlock
     0.21s 1.82% 93.95% 0.21s 1.82% crypto/des.permuteInitialBlock
     0.13s 1.12% 95.07% 0.13s 1.12% crypto/des.permuteFinalBlock
     0.12s 1.04% 96.11% 0.12s 1.04% crypto/sha1.block
     0.07s 0.61% 96.72% 7.47s 64.56% crypto/des.(*desCipher).Encrypt
     0.06s 0.52% 97.23% 11.34s 98.01% crypto/cipher.(*cbcEncrypter).CryptBlocks
     0.06s 0.52% 97.75% 0.06s 0.52% crypto/cipher.fastXORBytes
     0.06s 0.52% 98.27% 11.22s 96.97% crypto/des.(*tripleDESCipher).Encrypt

Having removed DES from the ciphers that Juju will use:

dooferlad@homework2 ~/dev/go/src/github.com/juju/juju $ go tool pprof $(which juju) /tmp/profile383480576/cpu.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
530ms of 570ms total (92.98%)
Showing top 10 nodes out of 45 (cum >= 60ms)
      flat flat% sum% cum cum%
     190ms 33.33% 33.33% 190ms 33.33% crypto/aes.encryptBlockAsm
     120ms 21.05% 54.39% 120ms 21.05% crypto/sha1.block
     110ms 19.30% 73.68% 110ms 19.30% syscall.Syscall
      30ms 5.26% 78.95% 290ms 50.88% crypto/cipher.(*cbcEncrypter).CryptBlocks
      30ms 5.26% 84.21% 30ms 5.26% crypto/cipher.fastXORBytes
      10ms 1.75% 85.96% 210ms 36.84% crypto/aes.(*aesCipher).Encrypt
      10ms 1.75% 87.72% 10ms 1.75% crypto/aes.(*aesCipherGCM).Encrypt
      10ms 1.75% 89.47% 200ms 35.09% crypto/aes.encryptBlock
      10ms 1.75% 91.23% 40ms 7.02% crypto/cipher.xorBytes
      10ms 1.75% 92.98% 60ms 10.53% io.(*LimitedReader).Read

This gets an 804M file across the wire much more quickly:
dooferlad@homework2 ~/dev/go/src/github.com/juju/juju $ time juju attach hacky name=/home/dooferlad/a-file.bin

real 0m37.085s
user 0m5.807s
sys 0m0.755s

Which is about 170Mbps

But not as fast as scp:
dooferlad@homework2 ~/dev/go/src/github.com/juju/juju $ time juju scp /home/dooferlad/a-file.bin 0:/home/ubuntu

real 0m6.269s
user 0m3.651s
sys 0m1.153s

This is 1GBps

[James Tunnicliffe (dooferlad)]

Actually after the first upload a second of the same file takes 7.3 seconds, which since the process takes about a second to start puts the transfer on par with SCP. While the first upload is happening Mongo is using plenty of CPU time, so perhaps growing its database rather quickly is the slowdown.

I should have a fix tomorrow.

[James Tunnicliffe (dooferlad)]

Uploads are limited by Mongo / gridfs. If you upload the same file twice to the same resource name then the second upload is much faster, but if you change the file contents then it is about 3x to 4x slower. You can watch Mongo chomp CPU time as it does this.

Unfortunately having sorted that out, similar speedups aren't being seen on the download side, which is unexpected - I thought they were a similar code path but one was an HTTP PUT and the other a GET. Getting the profiler out again.

[James Tunnicliffe (dooferlad)]

github.com/juju/juju/resource/state/resource.go contains:

func (u *unitSetter) Read(p []byte) (n int, err error) {
 n, err = u.ReadCloser.Read(p)
 here.Is(n)
 if err == io.EOF {
  // record that the unit is now using this version of the resource
  if err := u.persist.SetUnitResource(u.unit.Name(), u.resource); err != nil {
   msg := "Failed to record that unit %q is using resource %q revision %v"
   logger.Errorf(msg, u.unit.Name(), u.resource.Name,
                                      u.resource.RevisionString())
  }
 } else {
  u.progress += int64(n)
  // TODO(ericsnow) Don't do this every time?
  if err := u.persist.SetUnitResourceProgress(u.unit.Name(), u.pending, u.progress); err != nil {
   logger.Errorf("failed to track progress: %v", err)
  }
 }
 return n, err
}

That u.persist.SetUnitResourceProgress involves a database transaction and is called every 8kb of data, so for a large file there is massive contention on the database. Comment it out and the file is read at the expected rate (can read 800M to /dev/null in ~2 seconds).

I will propose a change that updates the progress once a second. Looks like the entire HTTP request takes about 5 seconds for an 800MB file.

[Kevin W Monroe (kwmonroe)]

Hey James, isn't "u.progress += int64(n)" adding 8 bytes (64 bits)? Not that it matters much, but building off what you said, I think this "massive contention on the db" would be 1000 times worse than an 8k chunk.

[Kevin W Monroe (kwmonroe)]

WOOHOO!! This is indeed fixed in beta 12:

...
unit-ibm-im-0: 2016-07-21 15:57:41 INFO unit.ibm-im/0.juju-log server.go:270 IBM IM: fetching the ibm_im_installer resource
unit-ibm-im-0: 2016-07-21 15:57:52 INFO unit.ibm-im/0.juju-log server.go:270 IBM IM: using /var/lib/juju/agents/unit-ibm-im-0/resources/ibm_im_installer/ibm_im_installer.zip as the ibm_im_installer resource
...

10 seconds for the 200MB resource that used to take 10 minutes. Nice work!