Repository navigation
PubSub with Python 3.5 spawns threads that don't die, eventually bringing the process to consume all CPU available #4563
Description
Hi,
I have searched for answers but haven't found anything matching this issue. The closest was #3965 but it might be a different problem.
- I'm using the Subscriber Client Python API.
- OS is Ubuntu 16.04.1 LTS (stock image off GCE)
- Python version is 3.5.2 (set up with virtualenv)
- google-cloud version 0.31.0, google-cloud-pubsub version 0.29.2, google-cloud-storage version 1.6.0
My code first initializes a subscriber client and storage client at startup like so:
storage_client = storage.Client(project=PROJECT_ID)
subscriber = pubsub.SubscriberClient()After ensuring it has a subscription it starts listening:
def listen_subscription(callback):
"""Listen for change events on GCS topic using supplied callback function"""
subscription_path = subscriber.subscription_path(PROJECT_ID, SUBSCRIPTION_NAME)
flow_control = pubsub.types.FlowControl(max_messages=1)
subscriber.subscribe(subscription_path, callback=callback, flow_control=flow_control)
syslog.syslog(syslog.LOG_INFO, 'Listening for messages on: ' + subscription_path)
while True:
time.sleep(60)No messages are ever sent on the topic, this is all on a completely idle system.
Eventually the thread count starts to creep up, and after an hour or two CPU usage spikes to 100%. I left it running overnight with some code in the loop printing all thread stacktraces. First I checked how many threads were running:
david@myinstance:~$ ps auxw -T | grep python | wc -l
461
Here's an excerpt of the stacktraces printed, and it goes on and on:
<CleanupThread(Thread-1178, started daemon 140501834020608)>
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 862, in run
self._target(*self._args, **self._kwargs)
File "/home/david/env/lib/python3.5/site-packages/grpc/_channel.py", line 185, in consume_request_iterator
request = next(request_iterator)
File "/home/david/env/lib/python3.5/site-packages/google/cloud/pubsub_v1/subscriber/_consumer.py", line 213, in _request_generator_thread
request = self._request_queue.get()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
<CleanupThread(Thread-335, started daemon 140504192370432)>
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 862, in run
self._target(*self._args, **self._kwargs)
File "/home/david/env/lib/python3.5/site-packages/grpc/_channel.py", line 185, in consume_request_iterator
request = next(request_iterator)
File "/home/david/env/lib/python3.5/site-packages/google/cloud/pubsub_v1/subscriber/_consumer.py", line 213, in _request_generator_thread
request = self._request_queue.get()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
<CleanupThread(Thread-44, started daemon 140505006462720)>
File "/usr/lib/python3.5/threading.py", line 882, in _bootstrap
self._bootstrap_inner()
File "/usr/lib/python3.5/threading.py", line 914, in _bootstrap_inner
self.run()
File "/usr/lib/python3.5/threading.py", line 862, in run
self._target(*self._args, **self._kwargs)
File "/home/david/env/lib/python3.5/site-packages/grpc/_channel.py", line 185, in consume_request_iterator
request = next(request_iterator)
File "/home/david/env/lib/python3.5/site-packages/google/cloud/pubsub_v1/subscriber/_consumer.py", line 213, in _request_generator_thread
request = self._request_queue.get()
File "/usr/lib/python3.5/queue.py", line 164, in get
self.not_empty.wait()
File "/usr/lib/python3.5/threading.py", line 293, in wait
waiter.acquire()
After checking out the google-cloud-python source code I noticed that the thread policy_class makes a distinction between Python 3.5 and 3.6:
I installed Python 3.6.3 and tried it out, and it doesn't seem to exhibit the same behavior – the number of threads stays limited. So in that sense I have a workaround, but I figured I would still report this in case someone else is seeing a similar problem.
Activity
dmontag commentedon Dec 10, 2017
I take that back – after left running, Python 3.6 seems to exhibit the same behavior of spiking CPU, though the number of threads hasn't increased like it did on 3.5.
Don't know if this helps, but here's the gdb thread printout:
ps auxw -Lshowed LWP 5052 as using all the CPU, with the others being at 0:Don't know if this helps, but figured I'd add it here in case something stands out.
dhermes commentedon Dec 11, 2017
@dmontag Thanks for this example. I'll try to reproduce today.
I'm hoping that the recent releases (in particular
0.29.4) have resolved this.dhermes commentedon Dec 12, 2017
@dmontag It's worth noting that the
3.6/2.7special branch is just to control how the thread pool executor names the threads in the pool. This feature was added in3.6It is also present in the
2.7backport.dhermes commentedon Dec 12, 2017
@dmontag So I am running a modified version of this, but it's essentially the same. I even attached the topic to bucket change notifications, though that doesn't seem relevant to the issue.
In
google-cloud-pubsub==0.29.2, I am seeing aThread-gRPC-ConsumeRequestIteratorturned into a zombie every 60s or so. These are threads spawned by gRPC as part of our bidirectional consumer. They stay open because we fail to sendSTOPto the queue they are attached to. This behavior was fixed by #4503 and included in the0.29.4release.I am going to pre-emptively close this issue (while I continue debugging). As of right now, my example has been running (with
0.29.2, since I'm trying to reproduce) for just over 12 minutes and the number of threads has grown to 17, but CPU usage is still hovering near 0%.Would you mind testing with
0.29.4in your "simulated conditions" and see if the issue is resolved?dmontag commentedon Dec 12, 2017
@dhermes Thanks for checking this one out. I tested on 0.29.4 yesterday, and it exhibits the same behavior of having a thread eventually spike and run at 100% sustained CPU – it takes about 65-70 minutes before the condition presents though. I updated my comment on #4274 to reflect this: #4274 (comment)
For now I'll have to run on 0.27.0 which has been running ok for the past 20-or-so hours. The Stackdriver dashboard reports Pull requests for 0.27 vs StreamingPull requests for 0.29 – maybe that's a place to start looking for differences on the client side.
dhermes commentedon Dec 12, 2017
Though I am loosely familiar with many Google APIs, I don't have deep knowledge of many of them. Would you mind pointing to docs for how I might create such a Stackdriver dashboard? (I have a general idea, but am overwhelmed by the sheer number of metrics for each Pub / Sub resource type in the metrics explorer.)
Thanks for continuing to help debug this. I wonder if it'd be possible for us to get a shared piece of code that we are both running? I've been tracking my experiments here https://github.com/dhermes/google-cloud-pubsub-performance and have yet to reproduce a CPU spike (though 5m is the longest anything has run so far).
dmontag commentedon Dec 12, 2017
For Stackdriver you basically click Monitoring on your GCP project in the regular GCP menu, go through the setup wizard, then either:
Go to Resources -> Cloud Pub/Sub, then click the topic, then click the subscription, and then it'll show the operations & requests on the right-hand side. Both kinds of operations need to be present in the stats for the charts to show.
Create a custom dashboard in the Stackdriver menu, then add a new chart for PubSub Subscription, add the StreamingPull Operations and Pull Message Operations dimensions, and save the chart. Again, you need both event types to have occurred to see the stats for both. It'll look something like this:
Not sure if that'll help track down the bug though, it was mostly a thought.
I can try to provide you access to an instance with my exact script toward the end of the week, and hopefully that might let you observe the behavior up close.
dhermes commentedon Dec 12, 2017
@dmontag I have at least been able to reproduce this (in
0.29.4) with a subscription that never receives a message. The CPU usage spikes somewhere between running 1h6m29s (0.4%), 1h6m34s (76.6%) and 1h6m39s (100.1% and stable at~100from here on out).I currently have no idea how this is happening. I'm using the Unix
gettidcommand to add a tracking hook inthreading.Threadand the CPU usage is coming with only 8 active pthreads owned by the parent.dmontag commentedon Dec 12, 2017
Sounds exactly like what I'm seeing. Good to hear that it's a reproducible problem – that's the first step toward fixing it :-)
Adding repro for #4563.
dhermes commentedon Dec 13, 2017
I think I've tracked it down. In the exact "spin worker" thread where the CPU usage begins to spike to 100%, there is a thread that checks the credentials. This is a sign that the credentials are being refreshed. This makes sense, since an access token has a lifetime of an hour plus some wiggle room.
/cc @jonparrott
theacodes commentedon Dec 13, 2017
theacodes commentedon Dec 13, 2017
dhermes commentedon Dec 14, 2017
I think the 60 minute mark / extra credentials check was a false
alarmsignal. I have verified withstracethat threads using 100% CPU are stuck in thePOLLIN/POLLHUPdance. I have also run withGRPC_TRACE=allandGRPC_VERBOSITY=debugso that may yield some ideas. (UPDATE: ZOMG the captured gRPC trace logs went from 64MB to 37GB once the CPU thrashing started. Holy moly.)Seems like grpc/grpc#13665 is an attempt at a stop-gap.
We may be able to address by tracking CPU usage and killing an active subscription based on this, but that wouldn't be very fun.
dmontag commentedon Dec 14, 2017
Interesting indeed. Any idea why 0.27 doesn't exhibit this? (I'm not familiar with the library internals)
dhermes commentedon Dec 14, 2017
It doesn't use a
StreamingPull.dmontag commentedon Dec 14, 2017
Do you think it's reproducible without PubSub-specific code? I.e. if a test case can be written that only uses gRPC to reproduce it?
dhermes commentedon Dec 14, 2017
@dmontag Yes, see grpc/grpc#9688
dhermes commentedon Dec 15, 2017
This issue actually corresponds to two distinct parts.
The first has been resolved (e.g. by #4444, #4472, #4498, #4503, #4554, #4558, etc.) and the second has it's own issue (I just made it) at #4600.