emailWorker stuck for 10 minutes

[damithc]

From dam...@gmail.com on March 14, 2014 07:53:18

This has been happening every hour since last night.

0.1.0.2 - - [13/Mar/2014:16:14:00 -0700] "POST /emailWorker HTTP/1.1" 200 0 " http://teammatesv4.appspot.com/feedbackSessionPublishedReminders " "AppEngine-Google; (+ https://code.google.com/appengine )" "teammatesv4.appspot.com" ms=599599 cpu_ms=381290 queue_name=email-queue task_name=10327766087814218065 exit_code=104 app_engine_release=1.9.0 instance=00c61b117ca304135253daf66d82669aea0802e3 W 2014-03-14 07:05:01.823 com.google.appengine.api.datastore.QueryResultsSourceImpl logChunkSizeWarning: This query does not have a chunk size set in FetchOptions and has returned over 1000 results. If result sets of this size are common for this query, consider setting a chunk size to improve performance. To disable this warning set the following system property in appengine-web.xml (the value of the property doesn't matter): 'appengine.datastore.disableChunkSizeWarning' W 2014-03-14 07:10:03.798 com.google.appengine.api.datastore.QueryResultsSourceImpl logChunkSizeWarning: This query does not have a chunk size set in FetchOptions and has returned over 1000 results. If result sets of this size are common for this query, consider setting a chunk size to improve performance. To disable this warning set the following system property in appengine-web.xml (the value of the property doesn't matter): 'appengine.datastore.disableChunkSizeWarning' I 2014-03-14 07:14:00.408 teammates.logic.automated.EmailAction logActivityFailure: TEAMMATESLOG|||feedbackSessionPublishedMailAction|||send published alert|||true|||Unknown|||Unknown|||Unknown|||Unknown|||Servlet Action failure in feedbackSessionPublishedMailAction
This request (2fbc211e52e523e0) started at 2014/03/13 23:04:00.915 UTC and was still executing at 2014/03/13 23:14:00.401 UTC.|||/emailWorker E 2014-03-14 07:14:00.409 teammates.logic.automated.EmailAction logActivityFailure: This request (2fbc211e52e523e0) started at 2014/03/13 23:04:00.915 UTC and was still executing at 2014/03/13 23:14:00.401 UTC. E 2014-03-14 07:14:00.409 teammates.logic.automated.EmailAction sendEmails: Unexpected error com.google.apphosting.api.DeadlineExceededException: This request (2fbc211e52e523e0) started at 2014/03/13 23:04:00.915 UTC and was still executing at 2014/03/13 23:14:00.401 UTC. at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1033) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1326) at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:268) at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96) at com.google.appengine.tools.development.TimedFuture.get(TimedFuture.java:42) at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63) at com.google.appengine.tools.appstats.RecordingFuture.get(RecordingFuture.java:108) at com.google.appengine.tools.appstats.RecordingFuture$ExtendedFuture.get(RecordingFuture.java:49) at com.google.appengine.api.utils.FutureWrapper.get(FutureWrapper.java:86) at com.google.appengine.api.datastore.FutureHelper.getInternal(FutureHelper.java:71) at com.google.appengine.api.datastore.FutureHelper.quietGet(FutureHelper.java:32) at com.google.appengine.api.datastore.QueryResultsSourceImpl.peekQueryResultAndIfFirstRecordIndexList(QueryResultsSourceImpl.java:162) at com.google.appengine.api.datastore.QueryResultsSourceImpl.loadMoreEntities(QueryResultsSourceImpl.java:104) at com.google.appengine.api.datastore.QueryResultsSourceImpl.loadMoreEntities(QueryResultsSourceImpl.java:91) at com.google.appengine.api.datastore.QueryResultIteratorImpl.ensureLoaded(QueryResultIteratorImpl.java:142) at com.google.appengine.api.datastore.QueryResultIteratorImpl.hasNext(QueryResultIteratorImpl.java:62) at org.datanucleus.store.appengine.query.RuntimeExceptionWrappingIterator$1.get(RuntimeExceptionWrappingIterator.java:50) at org.datanucleus.store.appengine.query.RuntimeExceptionWrappingIterator$1.get(RuntimeExceptionWrappingIterator.java:46) at org.datanucleus.store.appengine.query.QueryExceptionWrappers$1.get(QueryExceptionWrappers.java:51) at org.datanucleus.store.appengine.query.QueryExceptionWrappers$2.get(QueryExceptionWrappers.java:86) at org.datanucleus.store.appengine.query.RuntimeExceptionWrappingIterator.hasNext(RuntimeExceptionWrappingIterator.java:105) at org.datanucleus.store.appengine.query.LazyResult$LazyAbstractListIterator.computeNext(LazyResult.java:210) at org.datanucleus.store.appengine.query.AbstractIterator.tryToComputeNext(AbstractIterator.java:132) at org.datanucleus.store.appengine.query.AbstractIterator.hasNext(AbstractIterator.java:127) at org.datanucleus.store.appengine.query.LazyResult$AbstractListIterator.hasNext(LazyResult.java:169) at teammates.storage.api.StudentsDb.getStudentsForCourse(StudentsDb.java:149) at teammates.logic.core.StudentsLogic.getStudentsForCourse(StudentsLogic.java:85) at teammates.logic.core.FeedbackSessionsLogic.getFeedbackSessionResponseStatus(FeedbackSessionsLogic.java:867) at teammates.logic.core.FeedbackSessionsLogic.getFeedbackSessionResultsForUser(FeedbackSessionsLogic.java:742) at teammates.logic.core.FeedbackSessionsLogic.getFeedbackSessionResultsForStudent(FeedbackSessionsLogic.java:252) at teammates.logic.core.Emails.getStudentsWithSomethingNewToSee(Emails.java:540) at teammates.logic.core.Emails.generateFeedbackSessionPublishedEmails(Emails.java:497) at teammates.logic.automated.FeedbackSessionPublishedMailAction.prepareMailToBeSent(FeedbackSessionPublishedMailAction.java:71) at teammates.logic.automated.EmailAction.sendEmails(EmailAction.java:55) at teammates.logic.automated.EmailWorkerServlet.doGet(EmailWorkerServlet.java:58) at teammates.logic.automated.EmailWorkerServlet.doPost(EmailWorkerServlet.java:23) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166) at teammates.storage.datastore.DatastoreFilter.doFilter(DatastoreFilter.java:28) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at com.google.apphosting.utils.servlet.ParseBlobUploadFilter.doFilter(ParseBlobUploadFilter.java:125) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at com.google.apphosting.runtime.jetty.SaveSessionFilter.doFilter(SaveSessionFilter.java:35) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at com.google.apphosting.ut...

Original issue: http://code.google.com/p/teammatespes/issues/detail?id=1715

[damithc]

From dam...@gmail.com on March 13, 2014 17:22:51

Shawn, you may want to take a look at this as well. It is also related to fault tolerance.

Cc: leeshaw...@gmail.com
Labels: Scalability FaultTolarence

[damithc]

From dam...@gmail.com on March 13, 2014 20:06:14

It is caused by a feedback session published reminder (automatic) for a course of 400+ students. We may have to split this into individual tasks (1 task per student, instead of 1 task per session).

[damithc]

From dam...@gmail.com on March 13, 2014 20:37:43

KIV the splitting up by students. Arnold is trying to optimize the method. Meanwhile, this is a good candidate for a scalability test.

[damithc]

From arnold.k...@gmail.com on March 13, 2014 22:20:04

Backedout the thing that causes this issue (see issue 1716 ). The cause was because we queried all 400 students' FeedbackSessionResultBundle to figure out who has something new to see.

[damithc]

From hunur.kh...@gmail.com on March 13, 2014 22:46:33

I can split up the students in chunks of 20-30 to speed things up. I'll have to figure out a way to test for its scalability as its an automatic reminder.

[damithc]

From dam...@gmail.com on March 13, 2014 23:12:58

No need to split Hunar. It will make things worse. We have optimized it to make mass mailing faster.