Re: Strange quit behavior

[Eric Wong <normalperson@yhbt.net>]

Alex Sharp <ajsharp@gmail.com> wrote:
> >> Can you add "-f -e '!futex'" to the strace invocation so we see
> >> all the threads?  You can also add '-T' to get timing information
> >> to see how long each syscall takes or '-tt' to get timestamps
> >> in strace if you think it's useful.
> 
> Here's the result of strace with suggested flags on the old master.
> (To clarify, this is still the spinning CPU issue)
> 
> → sudo strace -v -f -e '!futex' -p 18862
> Process 18862 attached with 2 threads - interrupt to quit
> [pid 22170] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
> [pid 18862] select(4, [3], NULL, NULL, {3, 546106}) = 0 (Timeout)

<snip>

22170 is presumably the timer thread.

Did you send any signals to 18862 while you were making this strace?

If you did send a signal to 18862 while stracing, it's worrying it
didn't show up in your strace.  If you didn't send a signal, then
try sending a signal.

> >> Also, I assume you're using preload_app?  If you are, do you see this
> >> issue with preload_app=false?  I suspect there's some background thread
> >> that could be running in the master process taking up all the CPU time.
> >> Unicorn itself never spawns background threads.
> 
> I went ahead and ran strace with the same flags on the *new* master,
> and saw a bunch of output that looked bundler-related:
> https://gist.github.com/138344b5b19ec6ba1a4c
> 
> Even more bizarre, eventually the process started successfully :-/ Is
> it possible this had something to do with strace de-taching?

That looks like pretty normal "require" behavior.  strace would slow
down requires, a lot.

So this was with preload_app=true?  While you're debugging problems,
I suggest keeping preload_app=false and worker_problems=1 to minimize
the variables.

> You can see this in the unicorn.stderr.log file I included in the
> gist. Check out these two lines in particular, which occur 25 minutes
> apart:
> 
> I, [2011-08-23T02:15:08.396868 #22169]  INFO -- : Refreshing Gem list
> I, [2011-08-23T02:40:16.621210 #22925]  INFO -- : worker=1 spawned pid=22925

Wow, it takes 25 minutes to load your application?  strace makes the
application /much/ slower, so I can actually believe it takes that long.

Loading large applications is very slow under Ruby 1.9.2, there's some
pathological load performance issues fixed in 1.9.3.

So you're saying /without/ strace, CPU usage _stays_ at 100% and _never_
goes down?

> Question: If I turn on debug flags in unicorn, will I get much of this
> output in the unicorn.stderr log?

You'll get every exception that's thrown even if it's rescued.
Unicorn 3.x itself doesn't throw that many exceptions.


Generally, can you reproduce this behavior on a plain (empty) Rails
application with no extra gems?

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying