last day (14 days later) » 

4:09 PM
0
Q: Deferred Task Request deadline exceeded but work never started

David WardI have a task queue that handles deferred tasks that need to be processed in real time (I have heard this isn't a good idea but can't find any supporting documentation on this.). This queue is hit with an large influx of tasks (2500/min) and then often receives nothing for a minute or two. queu...

 
How did you conclude that the task isn't running? The log shows the request taking 641080ms which is a bit over the 10 min task queue execution time limit - probably when it was terminated. Maybe you're attempting to do too much stuff in one task or some endless loop is lurking in that stuff.
 
I concluded that the task isn't running as none of the logging messages associated with that deferred task ever appear. The only thing I get for these tasks is the Process terminated 10min later. I assumed that even if the process terminated I would still see my log messages. Is this not true? What do you mean by too much stuff? In general the deferred task executes within a second (except for the few that timeout).
An additional thought. The deferred task is passed a complex object that lazily loads and prepares a result. I guess it is possible there is something in there that causing an issue but without logging it's hard to know what.
 
The lack of logs might be an indication of something going wrong during processing. Maybe related - this Q&A suggests the deferred library might not be a good fit for high throughput apps: stackoverflow.com/questions/4909278/…. Just quessing, tho.
 
Ok so I moved away from the deferred library. I am using the taskqueue library myself now. So that should allow for a higher throughput as documented by google. I am having the exact same issue though. I end up with 7 or 8 tasks that don't seem to start. These tasks just sit in the queue and then time out after 10 minutes. Any ideas?
 
This makes me supect a bug even more. Are those 7-8 tasks a tiny minority of the tasks being processed (while the others being processed as expected)? If so - can you isolate the 7-8 ones and repro only with them? Might alo help is you post the task queue handler code
 
4:09 PM
Yes the others are being processed perfectly. The 7-8 tasks just don't start. I could try to capture the 2500 ish tasks that go through in one shot and see about replaying them to see if it's the same ones each time or random tasks. I will give that a shot. If that doesn't turn up anything I will post the task queue handler code.
I am thinking at this point that maybe new instances of my app are being initialized but they are loading too slowly. I'm going to pursue this theory and see where it takes me.
 
Yes, it's a possibility as well, mentioned in this guide: cloud.google.com/appengine/articles/deadlineexceedederrors. Logging itself is listed, too (seeing it in the traceback you added).
 
Yes, I was just reading that guide. I removed the logging and uploaded a new version of the app. I'm waiting to see if that has any effect on the DeadlineErrors. I'll post what I find out.
The strange thing is that these Deadline Errors are being raised on tasks starting from a Task Queue. They should have 10 minutes in which to run. Yet they seem to be stuck in the pending request queue.
 
A closer look at your traceback snippet shows an I msg at 13:48:22.970 showing the start of the task, followed by the E msg preceeding the actual traceback at 13:58:21.669 (i.e. ~10 min later). And the traceback includes this call from the process_netsapiens_event.py file (which I think is from your app, if true then it is proof that your code actually executes): logging.info("Process data for specific endpoint. Endpoint Key: %s", endpoint_key_url_safe)
 
Yes it did run in this instance. But this is the only one I found like this. Every other failure just has the E DeadlineExceededError with no I messages at all. I added such an example to the description above.
 
See my 1st comment, 641631ms in this last snippet. I think the only difference between the 2 cases is that in one the app manages to catch the DeadlineExceededError exception and print the traceback while in the other it doesn't. Per that guide: If the DeadlineExceededError is caught but a response is not produced quickly enough (you have less than a second), the request is aborted and a 500 internal server error is returned
 
4:16 PM
That is quite possibly true. It does explain the fact that some logging appears sometimes but not always. But if I am unable to get the logging details out how do I figure out why the task is taking 10 minutes? The only thing happening in here is that Channel Endpoints (channel api) are being sent messages.
 
are you processing a single message per taskq execution or multiple?
I know it's tricky to debug without logging, trying to understand the context better to see if/how that can be approached
 
I could be processing one or more message per taskq execution. It depends when the data enters the system. I looked at the payload size of the item on the taskq that get stuck and it's fairly small so there is only 1 or 2 messages grouped per task. I will step back and review it again. I must be overlooking something.
 
worst case you could just add a log "token" to a list in memcache/datastore, in case indeed the logging infra is the one causing the hiccups (possible, knowing that it should be quite some design to reliable handle multiple instances spawned dynamically, etc.)
you could set a limit to the number of messages processed at once and, if others are pending throw another task into the queue to continue processing in another taskq execution/instance - another 10 min.
 
That's not a bad idea actually. I'll do a code review first and then I'll write up a log token in memcache. I tried reducing the max_pending_latency on the app to 1s to reduce the messages going through a single instance. It didn't have any effect.
For my app if the message takes more then 20sec to process I would rather discard it and move on
That's why this 10min is really out there.
 
that's another option, should help I guess if indeed the issue is related to msg peaks
 
4:29 PM
Ok, well thanks. I'll play with it and let you know what I find.
 
k
have fun!
 
haha. Will do
 

last day (14 days later) »