PubSub locks up Node process at 100% CPU

[ehacke]

Environment details

• OS: Linux Mint 18.2 (dev)
• Node.js version: 8.3.0
• npm version: 5.3.0
• @google-cloud/pubsub version: 0.13.2 and 0.14

Steps to reproduce

1.Try to read from PubSub subscription (even if it's completely empty)
2. Node process goes to 100% of CPU and eventually is killed by K8S
3. Apologize for not having any good reproduction steps

So we've been having intermittent issues with reading from subscriptions attached to one specific topic using Node. The same code will run fine for weeks, and then suddenly every Node process attached to that subscription is pegged to 100% CPU until the process is killed externally. The crazy part is that even after the subscription is completely drained, this continues to happen. There is nothing to read, and yet it's completely locked up. It will continue to lock up every process attached to it for days, then suddenly stop.

I completely agree that this sounds like an implementation issue on my side, but hear me out.

Important details:.

• It does not seem to matter if there is anything in the subscription. An empty subscription also locks up the reading process.
• Running a flamegraph analysis (attached) shows that 97.18% of the time, some function called Node::MakeCallback is on the top of the stack. In my mind this points to the GPRC library being involved in the problem.
• The same application code functions fine using Kafka as the queue, with the only difference being the very simple read and write operations.
• Other Node applications, written significantly differently, also attached to subscriptions on that topic will also fail in the same way, but at different times. Which suggests to me that it's not an issue with the content of the subscriptions (it can even be empty), but the operation of reading from the subscription itself.
• We have many many other Node processes, using the same reading and writing code, connected to different topics, that never experience this issue.
• If it helps, another unique detail is that the source of this topic is our only Dataflow process

Is there anything else I can do to try to trace this problem?

I accept that I haven't given enough info for this be resolvable on your side, but I'm at a loss on how to debug this further.

[ehacke]

Things I tried that did not solve the issue:

• Recreating the Dataflow process that writes to the topic
• Recreating each individual subscription that is attached to the topic
• Recreating the processes that read from the topic
• Shutting down the source entirely and allowing the subscription to drain
• Shutting down every process involved simultaneously, waiting, and then bringing them all back up
• Doing all of these in all sorts of various orders and combinations

Things I tried that mysteriously did solve the issues:

• Deleting and recreating the topic itself

So yes, after doing every other thing I could think of, recreating the topic and then bringing the whole system back up seems to have resolved it, though it's still a mystery as to why.

[lukesneeringer]

Hey @ehacke,
Thanks for the bug report. This is extremely useful and we will dig into it and try to find out what is wrong.

One question while we work through this bug: Did the re-creation of the topic reset the issue or resolve it? I assume if you continued to subscribe to the stream, eventually you would have the problem again, yes? I am assuming it is a reset and not a resolution.

Assuming that it is a reset, then I agree with your other conclusions. I actually think there are two possibilities: gRPC itself is the problem, or else our connection pooling code is (in other words, we have a situation where we are creating more and more gRPC channels that are hammering the CPU).

We actually had an internal report of this problem, only reproducible in Kubernetes, that we believed fixed. Clearly it was not. :-( We will do what we can to track this down.

[lukesneeringer]

Hey @ehacke,
One more question. You said this happens with both 0.13.2 and 0.14.0, yes? And that it has occurred for some time?

This is really important because it actually identifies several points in our code we can rope off. In particular, if you get this behavior in 0.13.2, it means that connection pooling is not the culprit.

Thanks for your patience.

[ehacke]

@lukesneeringer

• In terms of reset vs resolve I'm not certain yet. So far it's been running with a fair amount of throughput for 2 hours without issue. That said, it occurred once before after running for weeks without issue, then resolved itself without any apparent action on our part after being a continuous problem for 3-4 days. But in all previous cases we didn't try recreating the topic itself, this was the first time.
• It definitely occurs in both 0.13.2 and 0.14.0. We had not seen it prior to that though we had other issues with previous versions and did not want to roll back. I attempted an update today to 0.14.0 to resolve the problem and it had no effect.

In the event that it happens again and it hasn't yet been diagnosed on your side, rather than deleting the topic, I'll just rotate to a new one and you can use the old one for testing. But I haven't seen the problem in any of our other topics so I don't know if we'll see it again.

[lukesneeringer]

@ehacke Thanks. I suspect there is an issue, but we desperately need a reliable repro case. If we can get one, I expect we can get to a resolution. :-) Thank you so much for the very useful report -- this was more information than I had previously.

[murgatroid99]

This does not look to me like a gRPC problem. Please keep in mind that in a flame graph like the one presented there the width of a bar indicates the amount of time between the start and end of a function, including the time spent in callee functions. So, while it appears that a lot of time is spent Node::MakeCallback (and, more to the point, grpc::node::CompleteTag), in fact almost all of that time is spent running code in the schema-inspector package. The fact that a gRPC function shows up in the flame graph as that wide bar near the bottom is simply a consequence of how gRPC's low-level code handles callbacks.

In short, your code is spending by far the most time in schema-inspector.

[ehacke]

@murgatroid99 You are absolutely right. I saw that too, but I was side-tracked by the belief that the other app that we also saw this lock-up issue on did not use that library, so I moved up the stack to the next common denominator. Upon further investigation, both apps use schema-inspector.

Still odd that the two apps would experience this issue at different times despite both reading from the same topic with the same code. And also that the issue would persist even after the subscription is empty. But both of those require more investigation on our side and are more likely to be our problem.

Anyways, thanks for taking a look and you can close this issue.

[stephenplusplus]

@lukesneeringer @callmehiphop do you have reason to believe there is more investigative work to be done here?

[callmehiphop]

@stephenplusplus yes, we've had multiple reports confirming the same thing, so even if this isn't gRPC related we still need investigate (which I currently am)

[ehacke]

We're having a repeat of this issue now, and we'll look into it on our side and report back what we find.

[ehacke]

And again, the interesting thing from our side in this case is that once again the two apps that are reading from this topic are receiving the same data, and parsing it in the same way using schema-inspector in the same code, but one is pinned to 100% CPU and the other is not.

My personal theory is that it's either something in the PubSub client library that eating the CPU directly, or somehow the messages are being modified by the PubSub reader in a way that causes the validation to eat CPU. But neither of those are validated yet, so I'll let you know.