Experiencing Extreme (10s+) Latencies with Pub/Sub

[MarkHerhold]

I described my situation in this GCP Pub/Sub forum post:
https://groups.google.com/forum/#!topic/cloud-pubsub-discuss/xhDvw63IVI8

I'm using (or trying to) GCP Pub/Sub by publishes a message on an existing subscription and topic every 5 minute and then acknowledging it on the same topic. I get monitoring alerts that the process is failing after waiting for 10 seconds and timing out a few times a day. My monitoring reports that there have been 109 timeouts over the past 24 hours. I think 10 seconds is a very high threshold for waiting for a message and would love to know what is causing this.

Kamal Aboul-Hosn said to create an issue on this repo and commented that it may be a perf issue. Here's what he said:

It looks like the Node.js Pub/Sub library has a performance issue. The way it looks to work is that it creates a pull request, waits for a response for that request, and then 10 milliseconds later creates a new pull request. This is not going to be the best way to minimize message end-to-end latency. To minimize that, one needs to have multiple outstanding pull requests simultaneously. As soon as a response comes, another request needs to be created. I recommend entering an issue in the google-cloud-node Github repository.

Even with that change, I expect that you will still occasionally see 10-second latencies for some messages.

Environment details

• OS: Debian 8
• Node.js version: 6.9.5
• npm version: 4.x.x
• google-cloud-node version: 0.8.0

Steps to reproduce

1. require @google-cloud/pubsub
2. create topic
3. create subscription
4. send a message on topic created above (this happens every 5 minutes)
5. immediately try to receive the same message on the same host
6. randomly experience 10s+ timeouts

Image from monitoring tool showing frequency of timeouts over the past 24 hours:

[stephenplusplus]

one needs to have multiple outstanding pull requests simultaneously.

@tmatsuo can you confirm we should be firing multiple pull requests when a user registers a message event (subscription.on('message', function(msg) {}))? And if so, is there any additional logic to consider, e.g. the amount of simultaneous requests?

As soon as a response comes, another request needs to be created.

This is the current behavior, with the exception of the 10 millisecond timeout. This can be changed:

var subscription = topic.subscription('sub-name', { timeout: 0 })

[kamalaboulhosn]

can you confirm we should be firing multiple pull requests when a user registers a message event (subscription.on('message', function(msg) {}))? And if so, is there any additional logic to consider, e.g. the amount of simultaneous requests?

Developer on the Cloud Pub/Sub team here. I can confirm that multiple outstanding pull requests is the correct behavior. The number of concurrent requests would have to grow fairly large before it would be an issue on the server side. 5-10 simultaneous pull requests would be reasonable.

[MarkHerhold]

This is still a significant problem for us (beyond performance). Is there an ETA on a fix? I'm not sure how GCP bugs are prioritized and do realize the API is Alpha quality.

[stephenplusplus]

On it!

[stephenplusplus]

@MarkHerhold could you give this a try:

$ npm install --save @google-cloud/pubsub@0.9.0-0

[MarkHerhold]

The good news is that Pub/Sub is way more consistent now. The bad news is that nearly everything is timing out. I'll poke around the code to see if we are doing something wrong.

[MarkHerhold]

@stephenplusplus Yeah, it breaks after a few sequential publish/subscribes. This isn't the most elegant test script, but it reproduces the problem for me, usually sometime after the 10th iteration. 🤔

const pubsub = require('@google-cloud/pubsub');
const client = pubsub(/* secret here */);

async function go() {

    const topic = (await client.createTopic('sometopic' + Math.floor(Math.random() * 2000)))[0];
    const subscription = (await topic.subscribe({
            ackDeadlineSeconds: 10,
            autoAck: false
        }))[0];

    for (let i = 0; i < 20; i++) {
        const start = Date.now();
        await new Promise(function(resolve, reject) {
            function onMessage(message) {
                if (message.data === 'test') {
                    subscription.removeListener('message', onMessage);
                    message.ack().then(resolve).catch(reject);
                }
            }

            subscription.on('message', onMessage);

            topic.publish('test');

            setTimeout(function() {
                subscription.removeListener('message', onMessage);
                reject('Pub/Sub timed out after ' + 10000 + ' ms');
            }, 10000);
        }).then(function() {
            console.log(`Pub/Sub resolved in ${Date.now() - start} ms`);
        }).catch(function(err) {
            console.error(err);
        });
    }
}

try {
    go();
} catch (err) {
    console.error(err);
}

[askmon]

@MarkHerhold I think that maybe your issue is similar to mine. The message counts as pulled, but can't be acked for some reason, then you have to wait until the ackDeadlineSecond time passes in order to try to receive it again...