aurora-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Maxim Khutornenko <ma...@apache.org>
Subject Re: Attempting to Push Aurora to ~11 requests/second
Date Thu, 19 Mar 2015 22:35:38 GMT
Same here. A single fork ran for 4 hours and I stopped it after 20K
tasks. Running 30 forks now for about an hour or so, no failure so far
(though vagrant IO ops stalled to a crawl).

On Thu, Mar 19, 2015 at 3:25 PM, Bill Farner <wfarner@apache.org> wrote:
> 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
View raw message