pubsub: Seeing many failed acks despite large MaxExtension and Synchronous

[jameshartig]

Client

PubSub

Describe Your Environment

fa2eb35 on GCE CentOS 7

Expected Behavior

See very minimal failed acks because expired.

Actual Behavior

Seeing lots (as in greater than 50%) of failed acks because expired.

Settings:

sub.ReceiveSettings.MaxOutstandingMessages = 3
sub.ReceiveSettings.MaxExtension = time.Hour
sub.ReceiveSettings.NumGoroutines = 1
sub.ReceiveSettings.Synchronous = true

The Ack Deadline for this subscription is 10 seconds.

Number of ack'd jobs per minutes:

Number of failed ack's because expired (via stackdriver) per minute:

We're ack'ing ~100/minute and stackdriver is reporting that 50-70 of those are ultimately being ignored because the deadline expired.

Time-to-ack 95th percentile:

For some reason there's only ~20 ModAcks being sent per minute:

But since the 50th percentile is <20 seconds maybe it's finishing quick enough not to warrant a modack?

We're acking most messages in less than a minute and since we have MaxExtension set to an hour I'd assume we'd have relatively 0 failed acks.

I'll be testing to see what happens if I disable Synchronous and if I increase the Ack Deadline to 60 seconds on the subscription.

[jameshartig]

Increasing the subscriptions Ack Deadline to 60 seconds has lowered the failed Ack count to only ~10/minute but I had thought that ModAck's should make it somewhat irrelevant what the actual deadline is so I'm still inclined to think this is a bug.

[jeanbza]

@fastest963 Thanks for reporting this. Did this happen recently? Is there something that could have caused this, like a dependency upgrade?

We shipped https://code-review.googlesource.com/c/gocloud/+/36050 yesterday: is it possible you have this commit? If so, could you try one commit before and see if that commit is borked?

[jameshartig]

@jadekler I tried downgrading to v0.33.1 and I'm still having the issue. I'm going to try setting Synchronous to false and see if that helps.

[jameshartig]

I disabled Synchronous and it actually made the problem worse. Now we have 0 ack's succeeding and 100% of them failing because of expired. If I look at the ModAck count, I see all of them succeeding and the rate of ModAck's now is matching the rate of Ack's so it seems like this fixed the "issue" of the ModAck's not matching the count of messages.

[jeanbza]

We're ack'ing ~100/minute and stackdriver is reporting that 50-70 of those are ultimately being ignored because the deadline expired.

The ack deadline, or the (gRPC) request deadline? Could you describe what "Failed Pull Ack Requests" is measuring?

For some reason there's only ~20 ModAcks being sent per minute:

We send an initial modack when a message (or batch of messages) is received. Furthermore, we send modacks to extend the lease whilst processing is happening. In v0.26.0 we change this to use a percentile distribution based on the time-to-ack to determine how frequently to send modacks. Ideally, each message would only have a single modack, since the percentile can accurately guess how much time you'll need. Rarely should you get more than one modack per message. So, the fact that you're only seeing 20 per minute is not strange to me.

I disabled Synchronous and it actually made the problem worse. Now we have 0 ack's succeeding and 100% of them failing because of expired. If I look at the ModAck count, I see all of them succeeding and the rate of ModAck's now is matching the rate of Ack's so it seems like this fixed the "issue" of the ModAck's not matching the count of messages.

What version did you upgrade from to see this problem? Is it possible to help us binary search this, or provide any additional details? Apart from the aforementioned change, there hasn't really been much change in pubsub.. 🤔

Also, I tried and failed to reproduce this with a very small, contrived example. I saw pretty steady acks (~120,000 per minute) before it plowed through all the messages in its topic.

(undelivered didn't drop to 0 because another topic has messages)

I probably don't have the same environment as you, though. Just adding a data point.

[jameshartig]

The ack deadline, or the (gRPC) request deadline? Could you describe what "Failed Pull Ack Requests" is measuring?

Specifically I'm using the stackdriver metrics to know how many failed ack requests there are.

subscription/streaming_pull_ack_message_operation_count{response_code="expired"}

I assume that's measuring the ack deadline. To be clear, we're not getting any errors back from the client, we're just noticing them via the stackdriver metrics and because we are seeing a large amount of duplicated messages.

The change to a distribution might have been the issue. Let me try going to an older version than v0.26.0 and see if I have the same problem. Let me try and also produce a simple test case. I can imagine the problem might arise because 50% of our jobs take less than a second but the 95th percentile is over a minute.

[jeanbza]

Ah! TIL that you can specify response code. For my short reproduction, it seems none expired. Also, FWIW, my expectation is that the distribution should have no affect - if a message lasts longer than the distribution thought it would, it simply results in two (or more) modacks instead of one. All that said, thanks for digging further, very interested to hear what you find out and get to the bottom of this.

[jameshartig]

Here's a reproduction script that actually causes more expired than success:
https://gist.github.com/fastest963/ad5f14e20cc624b9fc388712649d7839

Running that on a single n4-standard-4 in us-east1-c prints out:

~ INFO -- count received last minute -- count="319"
~ INFO -- count received last minute -- count="518"
~ INFO -- count received last minute -- count="466"
~ INFO -- count received last minute -- count="501"
~ INFO -- count received last minute -- count="464"
~ INFO -- count received last minute -- count="510"
~ INFO -- count received last minute -- count="515"
~ INFO -- count received last minute -- count="497"
~ INFO -- count received last minute -- count="494"
~ INFO -- count received last minute -- count="508"
~ INFO -- count received last minute -- count="503"
~ INFO -- count received last minute -- count="510"
~ INFO -- count received last minute -- count="477"
~ INFO -- count received last minute -- count="491"
~ INFO -- count received last minute -- count="512"
~ INFO -- count received last minute -- count="504"
~ INFO -- count received last minute -- count="481"
~ INFO -- count received last minute -- count="508"
~ INFO -- count received last minute -- count="503"
~ INFO -- count received last minute -- count="490"
~ INFO -- count received last minute -- count="493"
~ INFO -- count received last minute -- count="472"
~ INFO -- count received last minute -- count="515"
~ INFO -- count received last minute -- count="496"

and the metrics from:

subscription/pull_ack_message_operation_count

(Red is expired and Green is success)

For some reason this is exacerbating the issue and only 100/minute ack's are successful and almost 400/minute are failing. This was testing with the latest gocloud commit (411f107).

[jeanbza]

Hmmm... something fishy is going on. I ran that script (thank you for providing it) and did see some expired, though not nearly as many as you. Setting NumGoroutines=100 (and Sync=false, though I think NumGoroutines did it) seemed to drop it the expired messages to 0. See:

Is there a reason you're using NumGoroutines=1?

Also, this might be a good time to have one of the pub/sub folks take a look at your project and see if anything funky is going on. Would you like us to do so? If so, could you email me your project ID? I have one for you already, but probably good to re-send it just to make sure we know for-sure we're talking about the same project. :)

[jameshartig]

I'll send you an email with the projectID and the subscription. We were using NumGoroutines=1 for most of our subscriptions since it is the default (also for a lot of our subscriptions we only see a few messages a minute). For higher throughput subscriptions we set it higher.

I retried it with the same setup as you but I'm still seeing the number of expired be super high. There must be something wrong with the project or the region or something. I started with NumGoroutines=1 and then changed to NumGoroutines=100 but left Synchronous=true both times. It seems to be fine for a minute or two and then it switches to failing more than succeeding.

I switched at the dip around the 20th minute from 1 to 100 NumGoroutines.

Also, what flags did you run the script with, I saw your y-axis was over 6,000 but with the 1-120 second sleep and default of 500 consumers it shouldn't be able to do much more than 500/minute.

[jeanbza]

Good spot. It turns out I had a subscriber running in some k8s cluster. I am seeing this issue as well. Preliminary results indicate it is related to high modack values (which the distribution is happy to provide). Labeling as bug and investigating.