All starman workers have one (deleted) file open in lsof, seem hung on an flock call
Hi, I recently had a problem come up with my D1 app. I have the app writing the PID to the database at start and stop of a particular route, and I have two runs that never completed. I did an strace on the worker and it looked like this: [root@host ~]# strace -p 26508 Process 26508 attached - interrupt to quit flock(10, LOCK_EX lsof on that process gave me starman 26508 apps 10wW REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) (not sure, but I think the 10 in the flock call and the 10 in the 10wW mean that we're talking about the same file?). After a little more digging I found that every starman worker had that file open (except with 10w instead of 10wW for all but the one above and stracing a few of the other workers showed the same output ( "flock(10, LOCK_EX" ) as above. I started it up from a script with qx{ plackup --server Starman --port $port --workers 50 --env $env --pid=$run_file --daemonize bin/app.pl --error-log logs/$env.log } Anyone have any idea what that file would be, and whether this is indicative of any problem? Normally I expect to see a "listen(..." call when I do an strace, which I think means the worker is waiting for a connection. This looks to me like it's trying to get a lock on a file to write to it, but I don't know what that file would be, etc. Any help would be greatly appreciated. mike
On Tue, 18 Mar 2014 01:42:42 -0500 Mike South <msouth@gmail.com> wrote:
I recently had a problem come up with my D1 app. I have the app writing the PID to the database at start and stop of a particular route, and I have two runs that never completed.
I did an strace on the worker and it looked like this:
[root@host ~]# strace -p 26508 Process 26508 attached - interrupt to quit flock(10, LOCK_EX
lsof on that process gave me
starman 26508 apps 10wW REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted)
(not sure, but I think the 10 in the flock call and the 10 in the 10wW mean that we're talking about the same file?).
yeah, that'll be the same file descriptor - and yeah, looks like it's waiting to get an exclusive lock on it, but presumably another process already has that lock and hasn't released it - possibly as it's waiting on a lock on something the process you looked at has locked, leading to a deadlock situation? Do you use File::Temp within your process to acquire temporary files?
After a little more digging I found that every starman worker had that file open (except with 10w instead of 10wW for all but the one above and stracing a few of the other workers showed the same output ( "flock(10, LOCK_EX" ) as above.
That same exact filename? If so, odd.
On Tue, Mar 18, 2014 at 5:20 AM, David Precious <davidp@preshweb.co.uk>wrote:
On Tue, 18 Mar 2014 01:42:42 -0500 Mike South <msouth@gmail.com> wrote:
I recently had a problem come up with my D1 app. I have the app writing the PID to the database at start and stop of a particular route, and I have two runs that never completed.
I did an strace on the worker and it looked like this:
[root@host ~]# strace -p 26508 Process 26508 attached - interrupt to quit flock(10, LOCK_EX
lsof on that process gave me
starman 26508 apps 10wW REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted)
(not sure, but I think the 10 in the flock call and the 10 in the 10wW mean that we're talking about the same file?).
yeah, that'll be the same file descriptor - and yeah, looks like it's waiting to get an exclusive lock on it, but presumably another process already has that lock and hasn't released it - possibly as it's waiting on a lock on something the process you looked at has locked, leading to a deadlock situation?
Do you use File::Temp within your process to acquire temporary files?
Not directly. I don't know of it specifically being used by anything, but it is installed in my perlbrew so it definitely could be in use. I could put some debugging in there and see if it produces any clues.
After a little more digging I found that every starman worker had that file open (except with 10w instead of 10wW for all but the one above and stracing a few of the other workers showed the same output ( "flock(10, LOCK_EX" ) as above.
That same exact filename? If so, odd.
yes: [root@host ~]# lsof |grep /tmp/3j6mXZXwWM starman 26502 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26503 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26504 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26505 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26506 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26507 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26508 apps 10wW REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26509 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26510 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26511 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) starman 26512 apps 10w REG 8,22 0 24 /tmp/3j6mXZXwWM (deleted) ... According to the docs, this output means all the processes have it open for writing and 26508 has a write lock on the whole file. I'll see if I can get anything out of File::Temp--maybe adding debugging output there will give me an idea of what's so interesting to everybody. Thanks for looking at this with me. mike
participants (2)
-
David Precious -
Mike South