Python pubsub streaming pull ack high expired number

775 views
Skip to first unread message

Jeff Ye

unread,
Oct 18, 2017, 12:20:33 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, 

We are trying to upgrade our code to newer python pubsub version (0.28.3) which has streaming support. However, we are having problem with the unacknowledge messages number keep growing. 

We checked the metric and notice that the expired ack number is very high. (See attached graph).

Here are more informations:

1. Testing with python 3.5 and google-cloud-pubsub 0.28.3, on 2 CPU 7.5G GCE instance.

2. Same problem with the demo code which do nothing but just ack.

3. Only has problem with topic has high messages traffic, about 4000/s. For low traffic topic, it is working fine.

4. The java library (0.25.0-beta) working fine.

Do you have any idea about what we can do to fix this?

Thanks,

Jeff Ye
Screenshot at 2017-10-18 11-48-12.png

George (Cloud Platform Support)

unread,
Oct 18, 2017, 1:48:25 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hello Jeff, 

How did you specify the topic in Dataflow, exactly? When you provide a topic name, Dataflow automatically creates a subscription to that topic for you. Dataflow begins reading from the topic from the time your pipeline starts. Your app's code for the previous version of python pub/sub must be different, if not related to Dataflow. Some code adjustment might be due.  You may find related information on the "Pub/Sub I/O" documentation page. 

Jeff Ye

unread,
Oct 18, 2017, 2:47:43 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, George,

Thank you for the quick reply. 

However, the code is not for Dataflow. 

It is our own python script. The subscription is manually created from the admin console. BTW, the default ack deadline is set to 10 seconds.

Thanks,

Jeff Ye

George (Cloud Platform Support)

unread,
Oct 18, 2017, 3:42:30 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi Jeff, 

To exclude a coincidence, it would be of interest to see if situation reverts to normal if you revert to the old pub/sub python version. This is just to cover the case that external factors, such as networking, are at the origin of the delays. 

What happens if you increase the ack deadline value? 

Jeff Ye

unread,
Oct 18, 2017, 3:55:28 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, George,

It is fine with the old pubsub python version. But the old version is not using streaming. I think they are different endpoints, right?

We test with Java streaming and works fine. So, it is not likely the networking or GRPC service issue.

Increased default ack deadline of the subscription in admin console to 60 still has the same problem. Since the test code just receive and ack, so it won't be any delay in the callback function.

BTW, it seems like the problem happening while > 400 messages / s.

Thanks,

Jeff Ye

Kir Titievsky

unread,
Oct 18, 2017, 4:42:11 PM10/18/17
to Jeff Ye, Google Cloud Pub/Sub Discussions
Jeff, 

It looks like a lot of messages are not acknowledged in time based on the expiration counts in your graph. A silly first guess: your application takes a while to issue the ack() in the message handler and does so in the main thread. Meaning your message processing is synchronous.  To fix this, you have to process in parallel in multiple threads.  What do you think?

k

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.
 To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/d270b0bf-f623-4d18-a11a-d27f8e1a56ed%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

Jeff Ye

unread,
Oct 18, 2017, 4:58:12 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, Kir,

Thanks for the suggestion. Actually, my test code is very short:

import time
import datetime
import threading
from google.cloud import pubsub

subscriber = pubsub.SubscriberClient()

topic = 'projects/test-14378/topics/auction-unsold'

subscription_name = 'projects/test-14378/subscriptions/jeffye-test'

subscription = subscriber.subscribe(subscription_name)

lock = threading.Lock()
counter = 0

def callback(message):
    global counter

    size = len(message.data)
    logtime = int(message.attributes['log_time']) / 1000
    age = time.time() - logtime

    toPrint = False

    with lock:
        toPrint = (counter % 10000 == 0)
        counter = counter + 1

    if toPrint:
        print( "%s: Got msg size %d, %d seconds before" % (datetime.datetime.now().strftime('%H:%M:%S'), size, age))
    message.ack()


subscription.open(callback)

while(True):
    with lock:
        print("%d messages received" % counter)
        counter = 0
    time.sleep(1)

give just a few thousands in a second, I don't think the lock will affect the process too much.

Any modification you want me to make to test again?

Thanks,

Jeff Ye

Kir Titievsky

unread,
Oct 18, 2017, 5:10:38 PM10/18/17
to Jeff Ye, Google Cloud Pub/Sub Discussions
If I'm right I expect the following to happen:
1. If you simplify your handler to not use the global variable.  Maybe just do a print, perhaps piping it to a file to ensure you are not spending time waiting for lines to render on screen. With this we would expect your backlog to drop.
2. You say that you see this issue at 4K requests a second.  This means that if your handler has a 1/4000th of a second to do it's computation synchronously or it will fall behind. We can check how long your handler actually takes with two time.time() calls, and printing the result right before the return to the handler.  If I'm right you'll find that number to be about a millisecond.  If I'm wrong, it's much less than that. 

If we discover that the issue is that this sequential operation in a single thread is not fast enough in python, we can think about how to parallelize your code efficiently.  



To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsubscrib...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/a4e7317d-d6d2-448e-83f3-aed66da78ca2%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Jeff Ye

unread,
Oct 18, 2017, 5:19:13 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, Kir,

Thank you very much for the reply. I will try as you suggest. 

Just clarify, you meant the callback function from the pubsub subscriber is not threaded? I thought it is before, they's why I put the lock there before updating the counter.

Thanks,

Jeff Ye   
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.
 To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/a4e7317d-d6d2-448e-83f3-aed66da78ca2%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Kir Titievsky

unread,
Oct 18, 2017, 5:31:01 PM10/18/17
to Jeff Ye, Google Cloud Pub/Sub Discussions
my vague recollection is that python runs everything in a single thread by default. In other words, all your callbacks run in the same top level thread.  What the library parallelizes is all the mechanics of calling pub/sub and retrieving messages so that callback execution is not blocked by those.  Here's some discussion of this -- perhaps not the best -- but something to keep us moving. 

Jeff Ye   
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsubscrib...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsubscrib...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/95956240-c798-4d8a-97a5-753772bf0dcd%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Jeff Ye

unread,
Oct 18, 2017, 6:05:40 PM10/18/17
to Google Cloud Pub/Sub Discussions
Hi, Kir,

I test it with no output and counter, still has the high expired. See attach screen shot for matric (red color line).

use time.time() measure the callback function execute time got about: 0.000015.

Here is the code I used for test:

import time
import datetime
from google.cloud import pubsub

subscriber = pubsub.SubscriberClient()

topic = 'projects/test-14378/topics/auction-unsold'

subscription_name = 'projects/test-14378/subscriptions/jeffye-test'

subscription = subscriber.subscribe(subscription_name)

def callback(message):
    message.ack()

subscription.open(callback)

while(True):
    time.sleep(10)

Any idea what should I looking at?
Jeff Ye   
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-discuss+unsub...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/95956240-c798-4d8a-97a5-753772bf0dcd%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.
Screenshot at 2017-10-18 18-01-33.png

Kir Titievsky

unread,
Oct 19, 2017, 11:29:55 AM10/19/17
to Jeff Ye, Google Cloud Pub/Sub Discussions
Jeff, thanks for checking. Let me see if I can reproduce on my side and take it from there. Definitely not a behavior we intend. In the mean time could you please send me project number (you can find it in the console.cloud.google.com homepage support card or the support part of the app under the project name, as well as the subscription name where you are seeing this).

Jeff Ye   
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-dis...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-dis...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-dis...@googlegroups.com.



--
Kir Titievsky | Product Manager | Google Cloud Pub/Sub 

--
You received this message because you are subscribed to the Google Groups "Google Cloud Pub/Sub Discussions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cloud-pubsub-dis...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cloud-pubsub-discuss/90935374-8ac7-40f7-aaa8-d501ece6ab7c%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.
Reply all
Reply to author
Forward
0 new messages