Strange daemontools problem on AIX
Jurjen Oskam <[email protected]>
| Newsgroups | gmane.comp.djb.syslog |
|---|---|
| Message-ID | <[email protected]> |
Hi people,
I'm running daemontools on AIX 5.3. This works as you would expect, with
one exception. Sometimes, I'm seeing this:
# svstat /service/tijdreizen
/service/tijdreizen: down 564566 seconds, normally up, want up
This doesn't happen during normal system operation. However, on testing
systems, it sometimes happens that the system runs out of memory. When
that happens on AIX, all processes get sent a SIGDANGER. This signal
won't kill a process, it is meant to inform processes that paging space
is running low. If paging space fills up even more, the kernel will
not allow new processes to start; e.g. fork() will fail due to memory
exhaustion. Eventually, the kernel will start killing processes to free
up memory. When the out-of-memory situation no longer exists, system
operation is back to normal (provided that all required processes are
still running after the kernel process killing spree).
Back to normal, except sometimes for some daemontools controlled services.
The service above has the following run file:
#!/bin/ksh
sleep 1
exec 2>&1
print --
"***************************************************START**********"
print -- "*** PPROD ***"
su - oracle -c /usr/local/bin/tijdreis pprod
print -- "*** GLPP ***"
su - oracle -c /usr/local/bin/tijdreis glpp
print -- "*** CODAPP ***"
su - oracle -c /usr/local/bin/tijdreis codapp
print --
"***************************************************EINDE**********"
sleep 29
As you see, the expected lifetime of this service is not long (the
"tijdreis" command normally exits in seconds).
When the system is low on paging space and displaying the symptoms
described above, it frequently happens that services like the one here
have problems. Long running services keep on running, provided they
aren't killed by the kernel.
As you can see, this service was down for 564566 seconds. The service
was started with "svc -u", so it was supposed to start right after the
"sleep 29".
# date
Tue Dec 27 21:10:38 NFT 2005
# perl -e 'print scalar localtime(time-564566)'
Wed Dec 21 08:21:34 2005
# errpt | grep SYSVMM
C5C09FFA 1221082305 P S SYSVMM SOFTWARE PROGRAM ABNORMALLY TERMINATED
#
This tells me that the system was critically low on paging space the time
the service went down (the second item in the errpt output is a timestamp).
Only one (unrelated) process was actually killed by the kernel at 08:23,
but the failed fork()s most likely started to occur many minutes earlier.
# ps auxwww | cat -vet
[...]
root 356540 0.0 0.0 108 76 - A Nov 08 0:00 supervise log $
root 352452 0.0 0.0 108 76 - A Nov 08 0:00 supervise pprod+glpp-backup $
root 327796 0.0 0.0 80 32 - A Nov 08 0:00 /command/readproctitle
service errors:
..................................................................................................................................................................................................................................supervise:
warning: unable to fork for clear-errors, sleeping 60 seconds: out of
memory$
supervise: warning: unable to fork for tijdreizen, sleeping 60 seconds: out
of memory$
$
root 307388 0.0 0.0 108 76 - A Nov 08 0:00 supervise
log $
[...]
Indeed, fork failed.
# ps auxwww | grep 's[u]pervise tijdreizen'
root 340172 0.0 0.0 108 68 - A Dec 13 0:12 supervise tijdreizen
Supervise is running.
# ps -ef | grep 34[0]172
root 340172 344316 0 Dec 13 - 0:12 supervise tijdreizen
Supervise isn't the parent of any other process.
# ps -ef | grep '34[4]316'
root 295138 344316 0 Nov 08 - 0:00 supervise smbd
root 299172 344316 0 Nov 08 - 0:06 supervise clear-errors
root 303198 344316 0 Nov 08 - 0:00 supervise qmail-send
root 307388 344316 0 Nov 08 - 0:00 supervise log
root 311310 344316 0 Nov 08 - 0:00 supervise enable-printers
root 323770 344316 0 Nov 08 - 0:00 supervise log
root 331962 344316 0 Nov 08 - 0:00 supervise log
root 336034 344316 0 Nov 08 - 0:00 supervise dsmcad
root 340172 344316 0 Dec 13 - 0:12 supervise tijdreizen
root 344316 327796 0 Nov 08 - 2:06 /command/svscan /service
root 352452 344316 0 Nov 08 - 0:00 supervise pprod+glpp-backup
root 356540 344316 0 Nov 08 - 0:00 supervise log
root 360640 344316 0 Nov 08 - 0:00 supervise nmbd
root 364722 344316 0 Nov 08 - 0:00 supervise log
root 1151190 344316 0 Dec 13 - 0:00 supervise log
# ls -l supervise/
total 8
prw------- 1 root system 0 Dec 13 14:20 control
-rw------- 1 root system 0 Dec 13 12:34 lock
prw------- 1 root system 0 Dec 13 12:34 ok
-rw-r--r-- 1 root system 18 Dec 21 08:21 status
The status file was last written at the time of the memory starvation.
# svc -t /service/tijdreizen/
# svstat /service/tijdreizen/
/service/tijdreizen/: down 565325 seconds, normally up, want up
Hmmm, svc -t didn't help.
# svc -d /service/tijdreizen
# svstat /service/tijdreizen/
/service/tijdreizen/: down 565335 seconds, normally up
Still down of course, and no longer "want up".
# svc -u /service/tijdreizen
# svstat /service/tijdreizen/
/service/tijdreizen/: up (pid 1261646) 2 seconds
# ps -ef | grep 34[0]172
root 340172 344316 0 Dec 13 - 0:12 supervise tijdreizen
root 667752 340172 0 21:54:00 - 0:00 /bin/ksh ./run
And now it runs fine. No other black magic was needed to get it to run,
just svc -d and svc -u. Supervise now is the parent of the shell executing
the run script.
Something has gone wrong here. supervise doesn't seem to actually try again
after failing the fork and waiting 60 seconds. Why? I don't know. Right
now, there's still a service in "want up" state. I left it like that, since
the service is not critical, and so I can use it to investigate further.
Does anyone have a suggestion how I can diagnose (and hopefully solve) this
problem? I'd like my services to be started when they have to.
Thanks,
--
Jurjen Oskam