Description
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.