Pub/Sub: Server fails to deliver messages in a timely fashion

[dhoard-papajohns]

I have a Pub / Sub subscription with an ack deadline of 5 minutes.

Stack Driver shows there 7k+ unacknowledged messages, with the oldest message over 2.5 hours old.

My code, which is calling the REST pull API directly shows that messages are flowing but very slowly. When the code pulls messages, it's only a few at a time, some with large latency values (11 minutes, 22 minutes, etc. from publish time to receive time.)

gcloud beta pubsub subscriptions pull <subscription name> --limit 1000 --auto-ack | grep eventType | wc -l returns 0 message most of the time.

I would expect that with an ack deadline of 5 minutes, I would be able to pull bursts of messages ( up to maxMessages) every 5 minutes.

I was originally using the official Google Pub / Sub library (latest version) with the Subscriber class but would see random large latency issues.

I have had an open issue with support for at least 2 weeks, with no resolution.

The latest feedback from support was that messages aren't getting acked in time ... which based on my logging ... is because they aren't getting delivered in time / getting delivered already past the ack deadline.

[pongad]

@dhoard-papajohns Is it possible for you to share your code with us? It'd be useful to see what the code is doing.

I would expect that with an ack deadline of 5 minutes, I would be able to pull bursts of messages ( up to maxMessages) every 5 minutes.

If the ack deadline is 5 minutes, a pull will "reserve" the message for 5 minutes. If you don't acknowledge or modify-ack-deadline the message within that time, pubsub might give the message to someone else when they pull.

From your description: there are many unacknowledged messages but pull doesn't pull them. Assuming that pubsub server is working properly, this would mean the messages have already been pulled and "reserved" by someone else. Could something like this be happening?

@mdietz94 Do you have any other insight? Please let us know if we can provide any more info.

[dhoard-papajohns]

I have uploaded snippets of the relevant code that I can share.

In the application, I create a fixed thread pool ExecutorService with 100 threads, with each thread running the pullMessages method in Application.txt and adding the messages to a BlockingArrayQueue.

I have 400 threads processing messages in the BlockingArrayQueue via a take method /
metrics show that the BlockingArrayQueue is typically empty.

We have various use cases, in which we have to batch the messages when processing based on time periods (batches by minute, etc.)

PubSubMessagePullerClient.txt
Application.txt

[dhoard-papajohns]

Here is a Stack Driver screen shot that shows a case where messages stop getting delivered when performing the pullMessages method ... then for no apparent reason ... suddenly they are pulled and processed.

[mdietz94]

Other settings on the PullRequests can cause this. Make sure return_immediately is false and the deadline is set to at least 20s, preferably 40s or 1min. Additionally, the higher max_messages is set to (max 1000) the better we can deliver messages. Counterintuitively adding threads can decrease throughput when backlog is small because messages can get stuck waiting for the next pull request to hit the server, so fewer, larger Pulls will be more efficient, maybe 10 threads or so will be more reasonable. We've hit 100MB/s with that. Thanks,

…

On Thu, Mar 15, 2018, 7:44 AM Doug Hoard ***@***.***> wrote: Here is a Stack Driver screen shot that shows a case where messages stop getting delivered when performing the pullMessages method. [image: screen shot 2018-03-14 at 11 41 26 pm] <https://user-images.githubusercontent.com/28569618/37443236-49273f08-27e1-11e8-8c8a-8459f654e788.png> — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3025 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABvXasbYwpWkJN9IwySDfa5iTwaRRKF_ks5teeOkgaJpZM4SnKkK> .

[dhoard-papajohns]

@mdietz94 I have made the changes and will test / monitor the performance.

[dhoard-papajohns]

@mdietz94 The changes appear to have made not helped and actually made things worse.

We have a burst of messages every morning (around 300k.) Stack Driver shows the spike and shows it appears to get processed within 20 minutes .... yet we seem to have "stuck" or linger messages after the fact...

My logs show the time difference from receiving the message to calling acknowledge is sub-second.

[mdietz94]

Can you update the shared code? I can take a look to see if something stands out. Is 20 minutes longer than it normally takes to work through the backlog? What size are these messages?

…

On Thu, Mar 15, 2018, 5:03 PM Doug Hoard ***@***.***> wrote: @mdietz94 <https://github.com/mdietz94> The changes appear to have made not helped and actually made things worse. We have a burst of messages every morning (around 300k.) Stack Driver shows the spike and shows it appears to get processed within 20 minutes .... yet we seem to have "stuck" or linger messages after the fact... My logs show the time difference from receiving the message to calling acknowledge is sub-second. [image: screen shot 2018-03-15 at 8 59 20 am] <https://user-images.githubusercontent.com/28569618/37464738-a92f0ac2-282f-11e8-88e3-0450d947013c.png> — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3025 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABvXaucKtuiuhPjq9fFpsbUeOkVEKTDSks5temaJgaJpZM4SnKkK> .

[dhoard-papajohns]

20 minutes for the backlog is expected based on the nodes I have deployed (4 x 4 CPU machines) .... but I wouldn't expect the Oldest Unacknowledged message age scenario to happen.

After the spike is processed, we are sending heartbeat messages at a rate of 3 per minute.

The code is essentially the same.

I changed ...

max pull messages to 1000
returnImmediately to false
Apache HTTP Client socketTime to 60000 milliseconds (for the read timeout)
pull threads to 10

[dhoard-papajohns]

During this time period, our message load was fairly consistent.

I added code that will log a warning if any message takes longer than 2 minutes from pull (receive) time to ack time, but have not seen any warning messages.

[mdietz94]

I think this is the wrong place to debug this issue, since I think going further will require account information, and this is the wrong forum for that. This repository is focused on the client library, which I think if you can use, will solve this problem for you, but if that is not an option I recommend opening a support ticket, where we can collect more information to see what is going on in your project.

Feel free to escalate on the support ticket that you've opened, or to link them to this thread and ask that they ask for an engineer review, since I think given the information you have provided here it is worth a look from the engineering team.

Thanks,

[dhoard-papajohns]

@mdietz94 GCP Support has responded that "Our back-line team continues to investigate. Currently, they've isolated the issue to within a particular subsystem" ... so it's a server side system issue / not client issue. I'll work this issue via my support ticket.

Thanks