Alex Sharp <[email protected]> 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 - [email protected] http://rubyforge.org/mailman/listinfo/mongrel-unicorn Do not quote signatures (like this one) or top post when replying
