Nodejs-pubsub: High Latency To Publish

[Turniii]

Hello,

I am using the publish function in a basic way:

const gPubsub = require('@google-cloud/pubsub');
const pubsub = gPubsub({
      projectId: 'projectId',
    });
const publish = (message, cbkPublish) => {
      if (!message.topic)
        return cbkPublish('No PubSub topic specified');
      const topic = message.topic;
      delete message.topic;
      const publisher = pubsub.topic(topic).publisher();
      const buff = Buffer.from(JSON.stringify(message));
      publisher.publish(buff)
        .then(() => cbkPublish(null))
        .catch(err => cbkPublish(err));
    };
    return callback();
  }

The problem is that I am experiencing a long time to publish, for a buffer length of 352 it takes 3608 ms to publish. Is there some settings to publish faster ? Am I doing something wrong ?

Environment Details:

Node: 8.1.4
google-cloud/pubsub: 0.16.5

[stephenplusplus]

I have a feeling this is something that will be covered after #92 is merged. @callmehiphop what do you think?

[callmehiphop]

Actually publishing messages does not use the streaming API, so #92 will have no impact on this sadly.

@Turniii I would suggest caching the publisher outside of your function. When you call publish() we start buffering any additional messages and send them all in a batch. If you create a new publisher every time, this would result in all your messages being delayed by 1 second.

I believe you can also lower the duration that we buffer for by setting maxMilliseconds (by default it is 1000)

const publisher = topic.publisher({
  batching: {maxMilliseconds: 500}
});

[dwickstrom]

Hello,

I'm seeing this 1 second delay too and thinking about how I could cache the publisher in a nice way. What strikes me is how I have to send a message to be able to cache the publisher, and how this seems a bit unpractical to me.

Ideally what I'd like to be able to do, is to boot a publisher when my app starts, and then pass it around in the app. But since the order of arguments, probably due to some internal constraints, requires me to set the topic for the publisher to be able to boot it, then this becomes impossible.

Lowering that buffer like specified above, does work but I still think it's reasonable for me to want to cache the publisher without having to send a message first, and preferably also without setting the topic beforehand.

Does that make sense? 🤔

[callmehiphop]

What strikes me is how I have to send a message to be able to cache the publisher, and how this seems a bit unpractical to me

You don't need to send a message to cache the publisher.

Lowering that buffer like specified above, does work but I still think it's reasonable for me to want to cache the publisher without having to send a message first, and preferably also without setting the topic beforehand.

@kir-titievsky I'm not really sure I'm in a place to say, but does @dwickstrom's request seem reasonable to you? Seems simple enough to me and the usage would resemble something like this

const publisher = pubsub.publisher();

// this would throw an error since we haven't set a topic yet
let messageId = await publisher.publish(Buffer.from('Hello!'));

// sometime later

const topic = pubsub.topic('my-topic');
publisher.setTopic(topic);

// this would succeed
let messageId = await publisher.publish(Buffer.from('Hello, world!'));

[kir-titievsky]

Sure. Although I don’t think we have established that creating and
initializing the publisher takes a significant amount of time. Or did I
miss this?
On Wed, Mar 14, 2018 at 2:00 PM Dave Gramlich [e-mail]
wrote:

What strikes me is how I have to send a message to be able to cache the
publisher, and how this seems a bit unpractical to me

You don't need to send a message to cache the publisher.

Lowering that buffer like specified above, does work but I still think
it's reasonable for me to want to cache the publisher without having to
send a message first, and preferably also without setting the topic
beforehand.

@kir-titievsky https://github.com/kir-titievsky I'm not really sure I'm
in a place to say, but does @dwickstrom https://github.com/dwickstrom's
request seem reasonable to you? Seems simple enough to me and the usage
would resemble something like this

const publisher = pubsub.publisher();
// this would throw an error since we haven't set a topic yetlet messageId = publisher.publish(Buffer.from('Hello!'));
// sometime laterconst topic = pubsub.topic('my-topic');publisher.setTopic(topic);
// this would succeedlet messageId = await publisher.publish(Buffer.from('Hello, world!'));

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/googleapis/nodejs-pubsub/issues/93#issuecomment-373118518,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ARrMFleqUv4o5eet54LNwvSBW492BxRhks5teVrCgaJpZM4SmbPd
.

>

Kir Titievsky | Product Manager | Google Cloud Pub/Sub

[dwickstrom]

Unfortunately I started debating this without reading the source coding or knowing anything about the underlying architecture. But I'd expect an api that let's me understand which calls are expensive, so I can call them as rarely as possible. And so to me that part of the api feels obscured.

Although I don’t think we have established that creating and
initializing the publisher takes a significant amount of time

There has to be some kind of side effect going on, like establishing connections and asserting the topics are registered on the server side, that shouldn't have to be called every time I publish a message. And maybe it isn't, but I don't know that because the api won't let me know, by design.

Either way, I started wondering because I noticed the 1 second delay, which I got down to ~100 ms for the first, and then about ~20 ms for subsequent requests, by setting the buffer to 0. Don't know whether that should be considered "significant".

I ended up swapping Google pubsub for another solution, but still, thanks for replying 🙇

[kir-titievsky]

@dwickstrom Indeed, I think most of the latency issues are likely due to the high default batch size (see #96). Thanks for being patient and reporting your findings. Since you've switched to another solution, might you tell us more about:

1. Your latency expectations (what's a good enough latency)?
2. The other solution you've settled on?

[callmehiphop]

I'm going to close this since the original issue has since been resolved in the latest release.

[aayusharora]

@kir-titievsky
I am encountering the same problem.
If I make even 33 queries per second to app-engine which after validating publishes them to Pub/sub.

Each request-response cycle of pub/sub takes 170ms to complete. Till that completes, the request remains in App Engine Queue.

As App Engine can hold 80 concurrent requests in the queue per instance and the other instance take some time to spin up, it starts dropping requests and doesn't allow further requests to publish.

This is obviously because of the high latency of pub/sub.

I will appreciate your feedback and suggestions.

[kir-titievsky]

@aayusharora Have you tried reducing the publish batch sizes? See https://cloud.google.com/pubsub/docs/publisher#publisher-batch-settings-nodejs for sample. You should set maxMessages=1 and maxMilliseconds = 1. I'd love a report back on whether this solved the issue.

[kir-titievsky]

No, sorry I was not clear. The opposite: I'm asking you to turn off batching. It is on by default in the client library, if I remember correctly.

[aayusharora]

Any pointers to turn it off.
I have already removed the below snippet from the code @kir-titievsky

batching: {
      maxMessages: maxMessages,
      maxMilliseconds: maxWaitTime,
    },

[callmehiphop]

I don't think you can turn it off per se, but you should be able to do something like this

batching: {maxMessages: 1}

[kir-titievsky]

Yes, please, @aayusharora -- don't remove the settings. Set them explicitly. As I said, the default is to batch.

[aayusharora]

Thanks @kir-titievsky
The average latency is reduced to 80-100 ms from 170ms.

But, still, it's too high if I want to process 16k requests in one second.
As I explained earlier the app engine will allow only 80 concurrent requests in the queue and the other instance will take time to spin up.

The requests in the meantime will drop. Do you have any other suggestions to reduce this latency?

Any help will be highly appreciated !!

[kir-titievsky]

Can you point me to the specific limit or quota which on concurrent
requests that you are hitting here?

[aayusharora]

Maximum quota, I am going to expect 20-30k requests in a second.

The problem with the App Engine Standard Env is " Only 80 concurrent requests are allowed per instance"
Now it will take time to start in a new instance in autoscaling and requests will drop.

The more the latency, the more requests failure will occur and 80-100ms is also huge.

[kir-titievsky]

Ah, wait. This is per app engine standard instance. Why not just have
more instances?

On Tue, Nov 27, 2018 at 11:52 AM Aayush Arora (angularboy) <
[email protected]> wrote:

Maximum quota, I am going to expect 20-30k requests in a second.

The problem with the App Engine Standard Env is " Only 80 concurrent
requests are allowed per instance"
Now it will take time to start in a new instance in autoscaling and
requests will drop.

The more the latency, the more requests failure will occur and 80-100ms is
also huge.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/googleapis/nodejs-pubsub/issues/93#issuecomment-442133046,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ARrMFj_8U41GqH1hVbqQG_jqjIEXFojcks5uzW3qgaJpZM4SmbPd
.

--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub
https://cloud.google.com/pubsub/overview

[aayusharora]

@kir-titievsky
I already have auto scaling enabled but as you know spinning up the instance take some time.
Even if you start with a minimum of two, third one will take time.

What I am interested to know here is, what is the latency of a pub/sub request without even sending any payload ?

The latency is 80-100 ms at my end which I am unable to understand, it's very high.

Also, the no. of instances will be directly proportional to cost, hence I am more curious to decrease the latency.

[Prajjwal]

@kir-titievsky Experiencing the same latency issues, it hovers around ~200 ms regardless of whether we batch or not. Caching the client doesn't seem to affect performance. Any pointers? I'm pasting my test routes verbatim (these have no application logic, nor authentication that could affect performance) for reference.

const express = require ('express'),
  PubSub = require('@google-cloud/pubsub')
;

const Router = express.Router (),

  PubSubClient = new PubSub ({
    projectId: 'xxxxxxx-xxx'
  })
;

Router.get ('/', (request, response, next) => {
  response.render ('index', { title: 'Express' })
})

Router.post ('/singular', async (request, response, next) => {
  const client = PubSubClient
    .topic ('test')
    .publisher ({
      batching: {
        maxMessages: 1,
        maxMilliseconds: 1
      }
    })

  await client
    .publish (Buffer.from (JSON.stringify (request.body)))

  response.json ({ success: true })
})

Router.post ('/batched', async (request, response, next) => {
  const client = PubSubClient
    .topic ('test')
    .publisher ({
      batching: {
        maxMessages: 75,
        maxMilliseconds: 1000
      }
    })

  await client
    .publish (Buffer.from (JSON.stringify (request.body)))

  response.json ({ success: true })
})

const cachedClient = PubSubClient
  .topic ('test')
  .publisher ({
    batching: {
      maxMessages: 1,
      maxMilliseconds: 1
    }
  })

Router.post ('/cached', async (request, response, next) => {
  await cachedClient
    .publish (Buffer.from (JSON.stringify (request.body)))

  response.json ({ success: true })
})

module.exports = Router;

[kir-titievsky]

Any watchers of this interested in profiling the node client? Also: are these latency figures coming from request latency metrics reported by Stackdriver or some end-to-end measurements you are doing in the application?

@aayusharora apologies for the delay in response. I suspect there is some combination of server and client latency here. It might be worth profiling the client to cut that latency to a minimum, but I think the most important thing here is that you should get a latency that is somewhere between 10ms and 100ms. Meaning, even under the best circumstances your design choice of relying on App Engine for instant ramp up without keeping "hot" will keep you struggling.

There are a couple solutions here: batch the messages in a concurrent environment (e.g. Go on App Engine flexible environment), so you have only a single long RPC for many messages during spikes. Or keep more capacity around for App Engine standard.

The reason Pub/Sub takes >10ms to respond to a publish request is that the service is focused on scalable durable messaging: at least once delivery. To achieve that synchronous replication of message across availability zones has to happen. If you compare this to the latency of say a RabbitMQ cluster or a Kafka broker with async replication, you will of course see this as high latency. But the benefit is predictability of that performance.

@Prajjwal 200ms seems excessive, although, depends on where you are and if you are seeing this in one off test or continuous high (>>1/second) publishing. I don't think I'll be able to profile the client in detail to get to the bottom of this in time to be useful for you, but you should be able to get that number down. Perhaps you are seeing a high rate of errors for some reason so your latency is determined by the retries?

[troystackforce]

I experienced a similar issue recently. Our use case is to publish a single message to a pubsub topic from within a web client request/response cycle (an express route).

I wrote this test script to evaluate the time it takes to publish a message.

const PubSub = require('@google-cloud/pubsub');

const topicName = 'test-publish-speed-topic';
let savedTopic;
let savedPublisher;
const maxMessages = 1;
const maxMilliseconds = 10;
let totalDuration;
let loopCtr;

const getTopic = async () => {
  if (!savedTopic) {
    const pubsub = new PubSub();
    savedTopic = (await pubsub.topic(topicName).get({autoCreate: true}))[0];
  }
  return savedTopic;
};

const getPublisher = async () => {
  if (!savedPublisher) {
    const topic = await getTopic();
    savedPublisher = topic.publisher({
      maxMessages,
      maxMilliseconds,
    });
  }
  return savedPublisher;
};

const deleteTopic = async () => {
  const topic = await getTopic();
  if (topic) {
    await topic.delete();
    console.log(`topic ${topicName} deleted`);
    return;
  }
  console.log(`topic ${topicName} not found`);
};

const publish = async (data) => {
  const publisher = await getPublisher();

  const start = Date.now();
  await publisher.publish(data);
  const end = Date.now();
  const duration = end - start;
  totalDuration += duration;

  console.log(`publish: dur: ${duration}ms avg: ${totalDuration / loopCtr}ms`);
};

const run = async () => {

  // This will auto-create the topic. Do this before the run
  // so topic creation doesn't influence the results.
  await getTopic();

  // Exercise the publish function and console.log timing results
  totalDuration = 0;
  loopCtr = 1;
  for (; loopCtr <= 1000; ++loopCtr) {
    const data = {"foo": "bar"};
    const dataAsBuffer = Buffer.from(JSON.stringify(data));
    await publish(dataAsBuffer);
  }

  // Cleanup
  await deleteTopic();

};

run();

It takes ~120ms to publish a message using the above test script in cloud shell which is longer than we were hoping for. I reached out to the gcp slack channel and tscanausa tested it on his end using this curl command:

PROJECT='your-project'; TOPIC='your-topic'; curl -H "Authorization: Bearer $(gcloud auth application-default print-access-token)" -X POST https://pubsub.googleapis.com/v1/projects/$PROJECT/topics/$TOPIC:publish -d @data.json -H "Content-Type: application/json" -s -w @curl_format.txt

curl_format.txt

\n
  time_namelookup:      %{time_namelookup}\n
  time_connect:         %{time_connect}\n
  time_appconnect:      %{time_appconnect}\n
  time_pretransfer:     %{time_pretransfer}\n
  time_redirect:        %{time_redirect}n
  time_starttransfer:   %{time_starttransfer}\n
                     ------------\n
          time_total:   %{time_total}\n
\n

data.json

{  
   "messages": [{
      "data": "SGVsbG8sIFdvcmxkIQ=="
  }]
}

with similar results. I'm happy to help profile the node client if you think it will help? I tried batching 100 messages at a time and the publish time didn't vary much so it appears to take around 120ms whether I publish 1 message or x messages up to some value of x.

[kir-titievsky]

Troy, Thanks for submitting that example. Very helpful. One thing to note
is that your first publish call to Pub/Sub in XX minutes will generally
take longer since it requires extra information to be retrieved and cached
(e.g. auth bits). Do you observe comparable latency if you keep publishing?

On Fri, Dec 7, 2018 at 12:34 PM Troy Martin [e-mail]
wrote:

I experienced a similar issue recently. Our use case is to publish a
single message to a pubsub topic from within a web client request/response
cycle (an express route).

I wrote this test script to evaluate the time it takes to publish a
message.

const PubSub = require('@google-cloud/pubsub');

const topicName = 'test-publish-speed-topic';
let savedTopic;
let savedPublisher;
const maxMessages = 1;
const maxMilliseconds = 10;
let totalDuration;
let loopCtr;

const getTopic = async () => {
if (!savedTopic) {
const pubsub = new PubSub();
savedTopic = (await pubsub.topic(topicName).get({autoCreate: true}))[0];
}
return savedTopic;
};

const getPublisher = async () => {
if (!savedPublisher) {
const topic = await getTopic();
savedPublisher = topic.publisher({
maxMessages,
maxMilliseconds,
});
}
return savedPublisher;
};

const deleteTopic = async () => {
const topic = await getTopic();
if (topic) {
await topic.delete();
console.log(topic ${topicName} deleted);
return;
}
console.log(topic ${topicName} not found);
};

const publish = async (data) => {
const publisher = await getPublisher();

const start = Date.now();
await publisher.publish(data);
const end = Date.now();
const duration = end - start;
totalDuration += duration;

console.log(publish: dur: ${duration}ms avg: ${totalDuration / loopCtr}ms);
};

const run = async () => {

// This will auto-create the topic. Do this before the run
// so topic creation doesn't influence the results.
await getTopic();

// Exercise the publish function and console.log timing results
totalDuration = 0;
loopCtr = 1;
for (; loopCtr <= 1000; ++loopCtr) {
const data = {"foo": "bar"};
const dataAsBuffer = Buffer.from(JSON.stringify(data));
await publish(dataAsBuffer);
}

// Cleanup
await deleteTopic();

};

run();

It takes ~120ms to publish a message using the above test script in cloud
shell which is longer than we were hoping for. I reached out to the gcp
slack channel and tscanausa tested it on his end using this curl command:

PROJECT='your-project'; TOPIC='your-topic'; curl -H "Authorization: Bearer $(gcloud auth application-default print-access-token)" -X POST https://pubsub.googleapis.com/v1/projects/$PROJECT/topics/$TOPIC:publish -d @data.json -H "Content-Type: application/json" -s -w @curl_format.txt

with similar results. I'm happy to help profile the node client if you
think it will help? I tried batching 100 messages at a time and the publish
time didn't vary much so it appears to take around 120ms whether I publish
1 message or x messages up to some value of x.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/googleapis/nodejs-pubsub/issues/93#issuecomment-445307137,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ARrMFr26OK0RmfC9Dq2YMo4ArudCnsPvks5u2qbBgaJpZM4SmbPd
.

--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub
https://cloud.google.com/pubsub/overview

[troystackforce]

I think the latency stays the same but I can double check by running the script a few times back to back.

[troystackforce]

The latency gradually decreases as the test progresses.

The first publish:

publish: dur: 195ms avg: 195ms

The 1000th publish

publish: dur: 123ms avg: 124.426ms