Higher latency seen with pubsub publish call

[tmatsuo]

When issuing a Cloud Pub/Sub API publish call, and I'm experiencing a higher latency than expected.

expected: 70 - 100 ms
actual: ~300 ms

To reproduce this problem, you can run the pubsub-cmdline.js (inlined at the bottom) with the small modification below. Here is an example run:
$ ./pubsub-cmdline.js
Calling topic.publish at 1426005295668
Calling request at 1426005295846
Average: 314
Max: 314
1426005295846 - 1426005295668 = 178ms

It spends more than 1/2 of the total elapsed time before issuing the actual request. I suspect that there is a unnecessary RPC (presumably GCE metadata lookup?) before the actual API call. Since I'm using the service account from the json file, there shouldn't be such RPC. Do you think of anything that causes this?

Modification gcloud/lib/common/util.js: 400
just before calling request(authorizedReqOpts, function(err, res, body) {

        var now = new Date().getTime();
        console.log('Calling request at ' + now);

pubsub-cmdline.js

#!/usr/local/bin/node

//var projectId = process.env.GCLOUD_PROJECT_ID; // E.g. 'grape-spaceship-123'                                                                                                                 

var projectId = 'tmatsuo-pubsub-sample';

var gcloud = require('gcloud');
var pubsub;

pubsub = gcloud.pubsub({
  projectId: 'tmatsuo-pubsub-sample',
  keyFilename: '/home/tmatsuo/secret/pubsub.json'
});

//pubsub.createTopic('gcloud-node-topic', function(err, topic) {});                                                                                                                            
var topic = pubsub.topic('gcloud-node-topic');

var message = 'howdy';
var messageObject = { data: message };

var i;
var total = 0;
var max = 0;
var N = 10;
var counter = N;

for (i = 1; i <= N; i++) {
  var callPubSub = function() {
    var now = new Date().getTime();
    console.log('Calling topic.publish at ' + now);
    topic.publish(messageObject,
                  function(err) {
                    var end = new Date().getTime();
                    var elapsed = end - now;
                    if (elapsed > max) {
                      max = elapsed;
                    }
                    total += elapsed
                    counter -= 1;
                    if (counter == 0) {
                      console.log('Average: ' + total/N);
                      console.log('Max: ' + max);
                    }
                  });
  }
  setTimeout(callPubSub, 1000 * i);
}

I'm using the released version 0.12.0.

[stephenplusplus]

The only network call made is the publish API call. The slow start (is 178ms slow?) could be from reading and parsing your key file/wading through the deep Node call stack, as that's lazily done when the first API call needs to be made.

[tmatsuo]

Thanks Stephen. I confirmed that the subsequent calls are relatively faster (updated the snippets above, and I got average ~170ms).

is 178ms slow?
Yes relatively, but if it's only the first time, it's not a big problem. Thanks for clarification.

However, the actual API latency of ~170ms is slow too. When I do the same thing with golang, the average latency is around 70ms or so.

[ryanseys]

Not sure what we should do here for increasing the performance. It could be related to NodeJS performance vs. golang?

[tmatsuo]

Might be. Is the x2 latency expected? Do you know any good profilers to dig into such performance issue?

[ryanseys]

Is the x2 latency expected?

I'm not sure. Go is pretty fast but I can't see it being 2x faster with the network in the middle.

I've tried to profile other use case before with minimal luck. NodeJS seems mediocre at best for profile-ability. I might just have not thrown enough hours at the problem.

[Pampattitude]

Hi!

Are there any news on this issue?
I tried searching a bit for solutions, but can't seem to find the performance bottleneck myself.

Thanks!

[Pampattitude]

Hi,

Once again, high latency comes back as an issue, this time related to topic creation and subscription creation via gcloud-node.

Creating a topic takes about 3000ms, and creating an associated subscriber about 3000-3200ms.

Here is an example script:

'use strict';

var gcloud = require('gcloud');

var pubsub = gcloud.pubsub({
  projectId: 'myAwesomeProject',
});

console.time('Pub/Sub topic creation');
return pubsub.createTopic('test1', function(err, topicObj) {
  console.timeEnd('Pub/Sub topic creation');

  console.time('Pub/Sub subscriber creation');
  return topicObj.subscribe('subscriber_test1', {ackDeadlineSeconds: 600}, function(err) {
    console.timeEnd('Pub/Sub subscriber creation');

    return process.exit(0);
  });
});

The results:

Pub/Sub topic creation: 2883ms
Pub/Sub subscriber creation: 3147ms

The GCE instance used for testing is a GCE g1-small instance, located in europe-west1-d, with the following permissions, if that helps:

User info         Disabled
Compute           Read Write
Storage           Full
Task queue        Disabled
BigQuery          Disabled
Cloud SQL         Disabled
Cloud Datastore   Disabled
Cloud Logging     Write Only
Cloud Monitoring  Disabled
Cloud Platform    Enabled

Now, it is hard to know if the problem is actually the GCE instance, the Pub/Sub cloud @ GCE or the Node.js library itself from my position, but these response times are awefull nonetheless.

Would you know of any way to diagnose better this issue?

Thanks a bunch! I'm not a native english speaker, so my tone may sound rude, I hope I don't give that impression :x

[EDIT]: please note I did not provide any expected timed result or anything, because I have no idea what to compare it to. However, in the context of managed groups on GCE, it seems awefully slow and, in many cases with overcrowded REST servers, leads to even worse results and, sometimes, timeouts from the GCE load balancer.

3 seconds seems rea~lly slow :/

[jgeewax]

@tmatsuo : Any chance you can comment on this? Or loop in someone on the Pub/sub team who can?

[stephenplusplus]

@tmatsuo ?

[tmatsuo]

Do you still see ~3000ms latency? I tested your code and it shows:

$ nodejs index.js
Pub/Sub topic creation: 964ms
Pub/Sub subscriber creation: 1589ms

[stephenplusplus]

@Pampattitude - I'm going to close the issue as it appears it has resolved itself over the course of the last several months (sorry for that delay). If you're still experiencing the latency, please re-open.