pubsub: Old messages fail to ack because "expired"

[jameshartig]

This is related to #1247 but I'm filing a new issue since I have more data now and different questions. We've been running our "high throughput" queues with Synchronous=false but it's not clear what the disadvantage is of always setting it to true.

We don't usually see any failed acks (with true or false) but this time in particular we were catching up on a subscription that was >9 million and >2 hours behind. These "expired" are making it almost impossible to catch up since at some points over half of the messages we ack are failing and being retried.

I'm not sure if there's an issue where we're receiving already expired messages or if the client is holding onto messages too long (since we have Synchronous=false). Though I raised the Ack Deadline in the Google Console to 60 seconds and I didn't see any change (19:30 the change was made relative to the graphs below) so I'm inclined to think something is wrong here. I'm also not sure if we should just be using Synchronous=true instead?

Client

PubSub (aef6eeb)

Describe Your Environment

CentOS 7 on GCE (specifically in us-east1)
2 workers in each region with

MaxOutstandingMessages = 2000
Timeout = 15*time.Second
NumConsumers = 2000
NumGoroutines = 20 (10 x CPUs)
Synchronous = false

Expected Behavior

Acks succeed and we're not losing half of our ack's to "expired" errors.

Actual Behavior

We're seeing thousands of messages failing ack with the error "expired":

In #1247 (comment) you mentioned that if Synchronous=false then the client fetches more than the MaxOutstandingMessages. During that same time, looking at the pubsub_pull_count OpenCensus metric compared to our internal count of acks shows that we're acking all of the pulled messages:

Does the pubsub_pull_count not include the count "extra" messages that are pulled? If not, how can we determine that and graph it to aide with debugging.

This subscription in particular uses more CPU if a job is duplicated so more duplications cause the CPU to spike and for jobs to take longer to ack. The 95th percentile of time it takes to ack is < 5 seconds so I would imagine that even if the client fetched 2x MaxOutstandingMessages we could still ack all of them before the deadline (even with no ModAcks).

[jameshartig]

Here's a graph from the last hour of the success (yellow) vs failed (green):

It was going pretty well there for a while until 20:30 (UTC) where expired started happening a lot. We haven't made any changes on our side during this time period and the time to ack has stayed fairly constant:

And to clarify, for the last hour we were only running 1 instance of the application for this subscription.

[jameshartig]

I decided to set Synchronous=true just to see how it would perform since we had nothing to lose. I started up the second worker and set it to true on both workers, hoping it could work through the now almost 3 hour backlog. The change went live just after 21:30 and it looks like that has eliminated all of the "expired" messages but we took a 20% hit on the rate of messages. The net "success" number is ultimately way higher with no failed acks.

What I'm still confused about is how I can debug what was happening with Synchronous=false and how messages with a 60 second ack deadline were considered expired. Since the 95th percentile is <5 seconds to ack, we should be able to still handle the client fetching 6 x MaxOutstandingMessages, so either the client was fetching more than that or something else was going on.

[jameshartig]

Any update?

[hongalex]

Apologies, this slipped under my radar for a while. Thanks a lot for the detailed info between this and the older issue you referenced. I'll try to reproduce this and determine if pubsub_pull_count is inaccurate.

Just to be sure, have you seen this issue occur with versions of the client library between when you opened #1247 and now? I'm wondering if any of this might be related to changes we've made since then.

[jameshartig]

Just to be sure, have you seen this issue occur with versions of the client library between when you opened #1247 and now?

Yeah, I was reproducing using aef6eeb4a44b3d7557fe3c902e58cc2d51652a4e. As I mentioned I'm not sure yet if its a client or server issue. It seems to only happen when the backlog is filled with tons of events.

I managed to reproduce it with https://gist.github.com/fastest963/95c1148db456190fc61034accf3e85d1

I originally ran it with NumGoroutines = 1 and 100% of the were success but then once I raised it to NumGoroutines = 10 the expired count instantly rose. But also the messages had been sitting there for ~30 minutes by that point so I'm not sure if its because of the NumGoroutines or the length of time they've sat there unacknowledged.

(The above is pubsub.googleapis.com/subscription/pull_ack_message_operation_count grouped by response_code in stackdriver where green is success and blue is expired)

Here was the output when I started it with NumGoroutines = 10:

~ INFO -- starting receive
~ INFO -- last minute -- acked="36703" published="0" pullCount="38114"
~ INFO -- last minute -- acked="37558" published="0" pullCount="37666"
~ INFO -- last minute -- acked="37514" published="0" pullCount="37388"
~ INFO -- last minute -- acked="37664" published="0" pullCount="37806"
~ INFO -- last minute -- acked="37426" published="0" pullCount="37465"
~ INFO -- last minute -- acked="37485" published="0" pullCount="37455"
~ INFO -- last minute -- acked="37307" published="0" pullCount="37302"
~ INFO -- last minute -- acked="37541" published="0" pullCount="37462"
~ INFO -- last minute -- acked="37361" published="0" pullCount="36813"
~ INFO -- last minute -- acked="37461" published="0" pullCount="37994"
~ INFO -- last minute -- acked="37483" published="0" pullCount="37625"

Since the pullCount is using opencensus and I'm keeping track of acked separately I'm not sure how to relate those but there were some minutes where pullCount was less than acked so I'm still under the impression that it's not accurate since I would expect it to always be higher. I might be able to modify the script to make acked use opencensus as well but I'm not that familiar with opencensus.

I'll keep playing around with the script above and see if I can narrow down a better idea of what exactly is causing it.

Update: After running it a few more times. I'm leaning more towards it being caused by the age of the messages on the server. I ran the test with NumGoroutines = 10 and none of the ack's were erroring so instead I waited ~10 minutes and restarted the test script with ./test --num-publish 0 so it would skip the publishing step and then I started noticing a bunch of ack's failing with expired.

[jameshartig]

Any update on this? It seems like the issue is caused by jobs that have been sitting around on the server for a while (>10 minutes) so I'm not sure how else I can help, but let me know.

[hongalex]

Hi, thanks very much for the detailed report.

I believe that PullCount from the opencensus metrics does not currently account for errors, as indicated here. I'm currently working on improving the opencensus metrics recording to better handle error metrics which might help with debugging this issue. In short, we aren't recording opencensus metrics beyond simple count, where the plan is to tag individual metrics with success/error values. I'm starting this change with the topic publish metrics, but will be updating the subscription metrics to reflect this as well.

This doesn't address your issue right away, but hopefully the changes I make will help shed light on what's going on here. More information to follow soon.

[jameshartig]

Thanks for the update @hongalex. I'll keep an eye out and re-run my script posted earlier once the changes are out. If there are specific metrics you want me to focus on or record let me know.

[marrrcin]

This issue is similar to #1584, the common part being: 1. huge backlog of unprocessed messages, 2. more expired ACKs than valid ACKs. Configuration seems similar too.

[jameshartig]

@hongalex any update on this? I updated the title to reflect what the underlying issue is. Although I'm not sure how else to help without better metrics to understand if its a server problem or a client problem.

If I run the gist I posted earlier on the latest master:

$ ./pubsubtest
~ INFO -- starting publishing
~ INFO -- last minute -- acked="0" published="544766" pullCount="0"
~ INFO -- starting receive
~ INFO -- last minute -- acked="6914" published="455234" pullCount="8375"
~ INFO -- last minute -- acked="37496" published="0" pullCount="37570"

and let that run for 2-3 minutes then wait >10 minutes before running (I waited 30 but that's just because I had other stuff I was doing in the meantime):

$ ./pubsubtest --num-publish 0
~ INFO -- starting receive
~ INFO -- last minute -- acked="36631" published="0" pullCount="38025"
~ INFO -- last minute -- acked="37568" published="0" pullCount="37590"
~ INFO -- last minute -- acked="37509" published="0" pullCount="37594"
~ INFO -- last minute -- acked="37668" published="0" pullCount="37623"
~ INFO -- last minute -- acked="37423" published="0" pullCount="37450"
~ INFO -- last minute -- acked="37488" published="0" pullCount="37343"
~ INFO -- last minute -- acked="37318" published="0" pullCount="36808"
~ INFO -- last minute -- acked="37527" published="0" pullCount="38068"
~ INFO -- last minute -- acked="37367" published="0" pullCount="36918"
~ INFO -- last minute -- acked="37454" published="0" pullCount="38109"
~ INFO -- last minute -- acked="37500" published="0" pullCount="37294"
~ INFO -- last minute -- acked="37537" published="0" pullCount="36917"
~ INFO -- last minute -- acked="37368" published="0" pullCount="37520"
~ INFO -- last minute -- acked="37353" published="0" pullCount="37873"
~ INFO -- last minute -- acked="37589" published="0" pullCount="37769"
~ INFO -- last minute -- acked="37394" published="0" pullCount="37317"
~ INFO -- last minute -- acked="37467" published="0" pullCount="37499"
~ INFO -- last minute -- acked="37470" published="0" pullCount="37433"
~ INFO -- last minute -- acked="37773" published="0" pullCount="37664"
~ INFO -- last minute -- acked="37543" published="0" pullCount="37676"

You can see from the stackdriver graphs that many of the acks failed because expired. (Keep in mind that stackdriver is a few minutes behind):

I still see the problem where a majority of the messages fail to be acked because expired. You can actually see where the expired (green) end up being ~80% of the acks. This makes it extremely difficult to catch up if only 20% of the acks are actually successful. It definitely seems to be an issue with the length of time that the messages have been in the backlog. If I don't pause the receiving for a few minutes the problem is not as pronounced.