HTTPS performance regression

[orodeh]

I have seen a factor of four drop in https performance between node 0.12.7 and 0.10.40. Downloading a file with http and https, on a machine that has a 1GiB/sec internet connection, in the Amazon cloud, results in the following performance matrix:

Throughput
node version 0.10.40 0.12.7
http 88 MiB/sec 88 MiB/sec
https 75 MiB/sec 20 MiB/sec

While http performance remains the same, https performance has regressed significantly. The CPU is at 100% for both workloads. A git bisection indicates that the problem has been introduced sometime between 0.11.2 and 0.11.3.

The node program used is:

// Download a file with nodejs
//
var fs = require('fs');
var url = process.argv[2];

// calculate the protocol, by examining the url
var protocol = undefined;
if (url.indexOf("https") === 0)  {
    protocol = "https";
} else if (url.indexOf("http") === 0)  {
  protocol = "http";
} else {
  console.log("error: protocol must be http or https");
  process.exit(1);
}

if (url === undefined) {
  console.log("Error, must define the url");
  process.exit(1);
}
if (protocol === undefined) {
    console.log("Error, must define the protocol");
    process.exit(1);
}

function getLeaf(pathname) {
  return pathname.split('\\').pop().split('/').pop();
}

var trgFile = getLeaf(url);
var file = fs.createWriteStream(trgFile);

var requestModule = undefined;
if (protocol === "http") {
  requestModule = require('http');
} else {
  requestModule = require('https');
}

var request = requestModule.get(url, function(response) {
  response.pipe(file);
  file.on('finish', function() {
    file.close();
  });
}).on('error', function (err) {
    fs.unlink(trgFile);
    process.exit(1);
});

The shell script that drives it is:

#!/bin/bash -e

# 14MB file
url1="https://s3.amazonaws.com/1000genomes/phase3/data/HG00096/sequence_read/SRR077487.filt.fastq.gz"

# 79MB file
url2="https://s3.amazonaws.com/1000genomes/phase3/data/HG00108/sequence_read/ERR020229.filt.fastq.gz"

# 315MB
url3="https://s3.amazonaws.com/1000genomes/phase3/data/HG00106/exome_alignment/HG00106.chrom11.ILLUMINA.bwa.GBR.exome.20130415.bam"

#1.8GB file
url4="https://s3.amazonaws.com/1000genomes/phase3/data/HG00096/sequence_read/SRR062634_1.filt.fastq.gz"

chosenURL=$url1
trgFile=$(basename $chosenURL)

function output_results {
    START=$1
    END=$2
    SIZE=$3
    DIFF=$(echo "($END - $START)" | bc)
    TPUT=$(echo "$SIZE / ($DIFF * 1024)" | bc)

    echo "Time ${DIFF}"
    echo "Throughput ${TPUT} KB/sec"
}

# download a large file
function download_and_measure {
    /bin/rm -f $trgFile

    START=$(date +%s.%N)
    node download_one_file.js $chosenURL
    if [[ $? -ne 0 ]]; then
        echo "Error running node"
    fi
    END=$(date +%s.%N)

    SIZE=`ls -l $trgFile | cut -d ' ' -f 5`
    output_results $START $END $SIZE

    /bin/rm -f $trgFile
}

for i in 1 2 3; do
    download_and_measure
done

[orodeh]

A git bisection of the code shows that the regression was, probably, introduced between these two commits:

• 4ae96c8 (HEAD, refs/bisect/bad) crypto: do not move half-filled write head
• e92f487 (refs/bisect/good-e92f4879eb6c21d66ceaa819ae8f045226b74a3e) string_bytes: write strings using new API

The code differences can be viewed with a browser using this link:
e92f487...4ae96c8

Reading the code, it looks like the relevant changes are:

1. Memory allocation has changed
2. The Buffer and TLS modules have been rewritten
3. Streaming code has changed (src/stream_wrap.h)

Hope this helps narrow down the problem. Thank you,
Ohad.

[kislyuk]

@indutny, do you think you could help us out here? Most of the potentially related changes in the listed range, to tls and crypto, are by you. It seems that as a result, node 0.12 became more performant with small requests, but less performant with large (hundreds of megabytes) requests.

[indutny]

@orodeh are you using the same ciphers in both cases? Just curious if the bandwidth is the same when forcing cipher to be something like: AES128-SHA.

[thefourtheye]

Can we run the same against the latest io.js?

[orodeh]

Meanwhile, I spent time trying to figure out how node 0.12.7 was using the CPU. Here are flame-graphs generated while running the above node program to download a large S3 file from an Amazon EC2 worker.

HTTP (50MB/sec):

HTTPS (15MB/sec):

With TLS, it looks like a lot more CPU time is spent inside the network stack and cryptographic functions. I would love to include the original SVG graphs here, but that format is not supported here.

[orodeh]

I set the cipher to "AES128-SHA", but got the same results. Essentially, I did it this way:

agent = new https.Agent({
    "ciphers": "AES128-SHA"
});

options = {
    //    ciphers:
    agent: agent,
    host: x.host,
    path: x.path
};

var request = https.get(options, function(response) { 
...
}

The full program is:

// Download a file with nodejs
//
var fs = require('fs');
var url = require('url');
var http = require('http');
var https = require('https');

var webAddr = process.argv[2];

// calculate the protocol, by examining the url
var protocol = undefined;
if (webAddr.indexOf("https") === 0)  {
    protocol = "https";
} else if (webAddr.indexOf("http") === 0)  {
  protocol = "http";
} else {
  console.log("error: protocol must be http or https");
  process.exit(1);
}


if (webAddr === undefined) {
  console.log("Error, must define the url");
  process.exit(1);
}
if (protocol === undefined) {
    console.log("Error, must define the protocol");
    process.exit(1);
}

function getLeaf(pathname) {
  return pathname.split('\\').pop().split('/').pop();
}

var trgFile = getLeaf(webAddr);
var file = fs.createWriteStream(trgFile);

var requestModule = undefined;
if (protocol === "http") {
  requestModule = require('http');
} else {
  requestModule = require('https');
}

var agent = null;
var options = null;
var x = url.parse(webAddr);
if (protocol === "https") {
  agent = new https.Agent({
    "ciphers": "AES128-SHA"
  });

  options = {
    //    ciphers:
    agent: agent,
    host: x.host,
    path: x.path
  };
} else {
  options = {
    host: x.host,
    path: x.path
  };
}


var request = requestModule.get(options, function(response) {
  response.pipe(file);
  file.on('finish', function() {
    file.close();
  });
}).on('error', function (err) {
    fs.unlink(trgFile);
    process.exit(1);
});

[orodeh]

I get the same results with io.js version 3.00 (https://iojs.org/en/index.html).

15MB/sec https
50MB/sec http

[kislyuk]

@indutny, any thoughts on how to proceed here? This is blocking our 0.12 upgrade path, so we're eager to find the regression.

[indutny]

Looking.

[indutny]

I think it should be fixed by nodejs/node#2381 . May I ask you to give a try to this patch? It should apply almost cleanly to v0.12 (probably with context reduced to 0).

[orodeh]

Thanks!

Will do. I'll keep you posted.

[orodeh]

I tried several git repositories, only one repository improved performance. I used the following recipe:
$ git clone [email protected]:nodejs/node.git
#apply patch
$ ./iojs --version
v4.0.0-pre

Run the test with 'node' linked to the iojs executable. In that configuration I get the following performance:
48MB/sec https
80MB/sec http

This is a great improvement. Is there a stable branch that incorporates this fix? Patching the 0.12 branch did not yield any performance improvement.

Thanks!

[indutny]

@orodeh very interesting! Thanks for trying it out. May I ask you to give a spin to this patch too:

diff --git a/src/node_crypto_bio.h b/src/node_crypto_bio.h
index c4f2923..224467b 100644
--- a/src/node_crypto_bio.h
+++ b/src/node_crypto_bio.h
@@ -89,7 +89,7 @@ class NodeBIO {

   // Enough to handle the most of the client hellos
   static const size_t kInitialBufferLength = 1024;
-  static const size_t kThroughputBufferLength = 16384;
+  static const size_t kThroughputBufferLength = 64 * 1024;

   static const BIO_METHOD method;

You may want to keep both this and the previous together to get better results.

[orodeh]

I applied this too. Performance is better, but seems uneven, I don't know if it is the network, or the code. Here are six experiments downloading a 1.8GB file with https:
53 MB/sec
54 MB/sec
29 MB/sec
55 MB/sec
35 MB/sec
61 MB/sec

[indutny]

Partially fixed, I'll continue looking into this.

[orodeh]

@indutny, have you been able to make progress on back-porting this into the node 0.12.8 release? We would like to move from v0.10 to v0.12, but are blocked on this.

Thanks,
Ohad.

[indutny]

@jasnell may I ask you to help me with backporting this thing to v0.12?

[jasnell]

@indutny ... happy to help but it's likely going to be a couple of weeks. I'll assign to myself so I can keep track

[indutny]

Thank you, James!