Re: Strange quit behavior

[Alex Sharp <ajsharp@gmail.com>]

>> 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)
[pid 18862] wait4(-1, 0x7fffbb907d3c, WNOHANG, NULL) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067031, 459472514}) = 0
[pid 18862] fstat(7, {st_dev=makedev(202, 1), st_ino=31695,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:06}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067031, 459813102}) = 0
[pid 18862] fstat(11, {st_dev=makedev(202, 1), st_ino=31696,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:07}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067031, 459999675}) = 0
[pid 18862] fstat(13, {st_dev=makedev(202, 1), st_ino=31697,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:07}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067031, 460168995}) = 0
[pid 18862] fstat(14, {st_dev=makedev(202, 1), st_ino=31698,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:07}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067031, 460343593}) = 0
[pid 18862] select(4, [3], NULL, NULL, {6, 255959}) = 0 (Timeout)
[pid 18862] wait4(-1, 0x7fffbb907d3c, WNOHANG, NULL) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067037, 739352608}) = 0
[pid 18862] fstat(7, {st_dev=makedev(202, 1), st_ino=31695,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:16}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067037, 739570659}) = 0
[pid 18862] fstat(11, {st_dev=makedev(202, 1), st_ino=31696,
st_mode=S_IFREG, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:17}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067037, 739768755}) = 0
[pid 18862] fstat(13, {st_dev=makedev(202, 1), st_ino=31697,
st_mode=S_IFREG|01, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:17}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067037, 739951254}) = 0
[pid 18862] fstat(14, {st_dev=makedev(202, 1), st_ino=31698,
st_mode=S_IFREG|01, st_nlink=0, st_uid=1001, st_gid=1001,
st_blksize=4096, st_blocks=0, st_size=0, st_atime=2011/08/23-00:09:05,
st_mtime=2011/08/23-00:09:05, st_ctime=2011/08/23-02:37:17}) = 0
[pid 18862] clock_gettime(CLOCK_REALTIME, {1314067037, 740130965}) = 0
[pid 18862] select(4, [3], NULL, NULL, {9, 996190}^C <unfinished ...>

>> 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?

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

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

- Alex
_______________________________________________
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