aurora-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bill Farner <wfar...@apache.org>
Subject Re: Attempting to Push Aurora to ~11 requests/second
Date Thu, 19 Mar 2015 22:25:29 GMT
I've been running 10 forks of your script against a scheduler in the
vagrant environment for a little over an hour, and have not had luck at
inducing a crash yet.  Are you able to repro there?

Can you post the full scheduler log file from a repro of this?

-=Bill

On Thu, Mar 19, 2015 at 4:33 AM, Ryan Orr <ryanorr12@gmail.com> wrote:

> https://gist.github.com/ryanorr/b3736c03a9919f9b87dc
>
> Just a simple bash script. I run 10-15 of them in the background and it
> crashes usually in less than 30 mins as described. Thanks for looking into
> it.
>
> On Wed, Mar 18, 2015 at 7:19 PM, Bill Farner <wfarner@apache.org> wrote:
>
> > I'm slightly doubtful that GC is the issue (based on background from Ryan
> > in IRC), but i could be wrong.  Trying out a sample script would help us
> > confirm or deny, though.
> >
> > -=Bill
> >
> > On Wed, Mar 18, 2015 at 11:17 AM, Maxim Khutornenko <maxim@apache.org>
> > wrote:
> >
> > > This time gap of over 2 seconds suggests there may have been an
> > > intensive GC and/or IO operation that paused processing long enough
> > > for the ZK session timeout to expire:
> > >
> > > I0316 18:22:55.396108 20795 replica.cpp:508] Replica received write
> > request
> > > for position 22669
> > > I0316 18:22:57.621 THREAD1905
> > > org.apache.aurora.scheduler.mesos.MesosScheduler.Impl.logStatusUpdate:
> > > Received status update for task
> > >
> > > Do you see a "snapshot" or "backup" related log entires within 20
> > > seconds before the shutdown? If so, those are the known hotspots for
> > > generating a lot of GC and IO activities that may pause scheduler
> > > processing for a few seconds, which is long enough for the scheduler
> > > to lose leadership. The default ZK session timeout is 4 seconds, which
> > > may be too low to avoid leader re-election due to expired session in
> > > your case. You may want to validate this hypothesis by bumping up the
> > > default ZK timeout via a startup flag: --zk_session_timeout.
> > >
> > > On Wed, Mar 18, 2015 at 8:00 AM, Ryan Orr <ryanorr12@gmail.com> wrote:
> > > > We're attempting to get Aurora to handle 11 job requests a second. We
> > > > realize we're going to be limited by the resource intensive nature of
> > the
> > > > CLI and will be giving Herc a shot here soon; however we seem to get
> > the
> > > > scheduler to crash in less than an hour while submitting about 2
> > > > jobs/second.
> > > >
> > > > The job we're submitting simply echo's "Hello" ever minute for 5
> > minutes,
> > > > then exits. Here's what the logs look like at the time of the crash:
> > > >
> > > > I0316 18:22:54.348743 20799 log.cpp:680] Attempting to append 1650
> > bytes
> > > to
> > > > the log
> > > > I0316 18:22:54.348808 20799 coordinator.cpp:340] Coordinator
> attempting
> > > to
> > > > write APPEND action at position 22668
> > > > I0316 18:22:54.348989 20799 replica.cpp:508] Replica received write
> > > request
> > > > for position 22668
> > > > I0316 18:22:54.352383 20799 leveldb.cpp:343] Persisting action (1671
> > > bytes)
> > > > to leveldb took 3.370462ms
> > > > I0316 18:22:54.352414 20799 replica.cpp:676] Persisted action at
> 22668
> > > > I0316 18:22:54.352565 20799 replica.cpp:655] Replica received learned
> > > > notice for position 22668
> > > > I0316 18:22:54.356220 20799 leveldb.cpp:343] Persisting action (1673
> > > bytes)
> > > > to leveldb took 3.634224ms
> > > > I0316 18:22:54.356253 20799 replica.cpp:676] Persisted action at
> 22668
> > > > I0316 18:22:54.356266 20799 replica.cpp:661] Replica learned APPEND
> > > action
> > > > at position 22668
> > > > I0316 18:22:54.561 THREAD127
> > > > org.apache.zookeeper.ClientCnxn$SendThread.startConnect: Opening
> socket
> > > > connection to server sandbox01/192.168.4.101:2181
> > > > I0316 18:22:54.563 THREAD127
> > > > org.apache.zookeeper.ClientCnxn$SendThread.primeConnection: Socket
> > > > connection established to sandbox01/192.168.4.101:2181, initiating
> > > session
> > > > I0316 18:22:54.564 THREAD127
> > > > org.apache.zookeeper.ClientCnxn$SendThread.readConnectResult: Session
> > > > establishment complete on server sandbox01/192.168.4.101:2181,
> > > sessionid =
> > > > 0x14c03fdca89bc0f, negotiated timeout = 4000
> > > > I0316 18:22:55.374 THREAD143
> > > >
> > org.apache.aurora.scheduler.async.OfferManager$OfferManagerImpl.addOffer:
> > > > Returning offers for 20150304-172015-1711581376-5050-15195-S5 for
> > > compaction
> > > > I0316 18:22:55.374 THREAD143
> > > >
> > org.apache.aurora.scheduler.async.OfferManager$OfferManagerImpl.addOffer:
> > > > Returning offers for 20150304-172015-1711581376-5050-15195-S3 for
> > > compaction
> > > > I0316 18:22:55.394 THREAD137
> > > > com.twitter.common.util.StateMachine$Builder$1.execute:
> > > >
> > >
> >
> 1426265234214-root-prod-gl6e9DL4vM3J0XTxM0k9GMT4QeXRTgYz-0-8e0df05c-b6c7-40bd-924f-b858f39da316
> > > > state machine transition PENDING -> ASSIGNED
> > > > I0316 18:22:55.394 THREAD137
> > > > org.apache.aurora.scheduler.state.TaskStateMachine.addFollowup:
> Adding
> > > work
> > > > command SAVE_STATE for
> > > >
> > >
> >
> 1426265234214-root-prod-gl6e9DL4vM3J0XTxM0k9GMT4QeXRTgYz-0-8e0df05c-b6c7-40bd-924f-b858f39da316
> > > > I0316 18:22:55.394 THREAD137
> > > >
> org.apache.aurora.scheduler.state.TaskAssigner$TaskAssignerImpl.assign:
> > > > Offer on slave {URL} (id 20150304-172015-1711581376-5050-15195-S2) is
> > > being
> > > > assigned task for
> > > >
> > >
> >
> 1426265234214-root-prod-gl6e9DL4vM3J0XTxM0k9GMT4QeXRTgYz-0-8e0df05c-b6c7-40bd-924f-b858f39da316.
> > > > I0316 18:22:55.395851 20795 log.cpp:680] Attempting to append 1451
> > bytes
> > > to
> > > > the log
> > > > I0316 18:22:55.395921 20795 coordinator.cpp:340] Coordinator
> attempting
> > > to
> > > > write APPEND action at position 22669
> > > > I0316 18:22:55.396108 20795 replica.cpp:508] Replica received write
> > > request
> > > > for position 22669
> > > > I0316 18:22:57.621 THREAD1905
> > > >
> org.apache.aurora.scheduler.mesos.MesosScheduler.Impl.logStatusUpdate:
> > > > Received status update for task
> > > >
> > >
> >
> 1426265234214-root-prod-gl6e9DL4vM3J0XTxM0k9GMT4QeXRTgYz-0-8e0df05c-b6c7-40bd-924f-b858f39da316
> > > > in state TASK_STARTING: Initializing sandbox.
> > > > I0316 18:22:58.396 THREAD137
> > > > com.twitter.common.application.Lifecycle.shutdown: Shutting down
> > > application
> > > > I0316 18:22:58.396 THREAD137
> > > >
> > >
> >
> com.twitter.common.application.ShutdownRegistry$ShutdownRegistryImpl.execute:
> > > > Executing 7 shutdown commands.
> > > > I0316 18:22:58.561 THREAD137
> > > >
> > >
> >
> org.apache.aurora.scheduler.app.AppModule$RegisterShutdownStackPrinter$2.execute:
> > > > Shutdown initiated by: Thread: TaskScheduler-0 (id 137)
> > > > java.lang.Thread.getStackTrace(Thread.java:1589)
> > > >
> > > > The stack trace doesn't show anything interesting, I can't figure out
> > why
> > > > it just randomly issues a shutdown. Let me know if there's anything
> > else
> > > > that would be helpful from the log, we're on an internal network so I
> > > can't
> > > > just copy/paste the logs over.
> > >
> >
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message