We've been having a curious problem recently in DEV@Cloud where we see a Jenkins instance fork itself and the child process consumes 100% of a CPU. The child process is a fork in every sense: same cmdline parameters, file descriptors, etc. The parent process was still responsive, so our monitoring systems didn't usually detect this problem.Whenever I've seen this, I would scratch my head, poke around a bit, and not really get anywhere with it. Today, I had the time to isolate one of these gremlins and see what was going on.
Strangely, the child process was unresponsive to strace or pstack, so I went back to the parent process and gave it a kill -3
Since Jenkins uses such descriptive thread names, I was able to find the Git polling log for the job and saw that it attempted to launch 6 days ago, and was still stuck. Even better, the timestamp on that git polling log and the timestamp on my Mysterious Jenkins Fork were exactly the same!
So, why was this git process being launched as a new jenkins process? I discovered this when I googled for "UnixProcess.forkAndExec" on a lark, and came across this wiki page in the first result. As per that page:
In Unix, the way Java launches a new process is first by forking the current process and then exec-ing. Therefore, for a brief period between fork and exec, there's temporarily two instances of your application server running on your system. If the application server you are running Hudson in is using 1GB virtual memory, this means you temporarily need 2GB of virtual memory
I did not know that! The wiki page goes on to talk about needing more swap space as a consequence of this. But we aren't getting that particular error message, so it doesn't seem likely that memory is our problem. Nevertheless, there are other resources that a process needs, such as file descriptors.
How many file descriptors does a Jenkins instance need? Based on what I've seen by doing a lsof -p
Interestingly, Fedora defaults to a maximum of 1024 open file descriptors (ulimit -n) for a given user. So if a single Jenkins instance forks to exec git, then it could temporarily go over this limit. I'm not sure why the process responds to this limit by consuming 100% of CPU instead of throwing an error -- this seems like a bug in Linux or the Sun JVM.
However, this would help explain why we rarely see this problem -- we're right at the maximum for normal case, and may only hit it when multiple git SCM pollings are running for a given Jenkins instance. We're going to increase the maximum open files a bit (the nofile setting in /etc/security/limits.conf) and see if that helps alleviate this issue.
[Update] Martin Ellis points out that Linux uses copy on write when forking so you shouldn't need to have double the memory available. He also points out the fork man page which may suggest that file handles are shared between the two processes:
The child inherits copies of the parent's set of open file descriptors. Each file descriptor in the child refers to the same open file description (see open(2)) as the corresponding file descriptor in the parent. This means that the two descriptors share open file status flags, current file offset, and signal-driven I/O attributes (see the description of F_SETOWN and F_SETSIG in fcntl(2)).
This might suggest that our guess (open file limits exceeded causes CPU spin) is malarkey. I'm not sure how to know for sure, though.
I'm curious if this actually is the underlying issue, or just a red herring (since the 100% CPU thing is a strange symptom, usually you get an immediate failure when you run against resource limits like this).
ReplyDeletePlease update with your conclusions once you have them :)
Yeah, good point. It's important to point out that we are guessing at the root cause a bit. The next time I see the issue, I plan to try a jstack on it. kill -3 hasn't worked presumably because the stderr is being sent to the parent process.
ReplyDeleteFork/exec has always had its issues.
ReplyDeleteBest solved by creating a helper process while fork is cheap, as described in http://developers.sun.com/solaris/articles/subprocess/subprocess.html (Greg Nakhimovsky, May 2006)
Different unixen and the likes have different ways of dealing with it: early bsd had vfork() which had issues of its own, posix_spawn() looks appealing, but may still depend on fork()/exec() underneath.
Copy on write will solve the VM pressure, but not the other limits.
In the past I've seen a similar issue in Solaris, which is discussed in https://wiki.jenkins-ci.org/display/JENKINS/Solaris+Issue+6276483
ReplyDeleteI find it unlikely that the file descriptor limit is the cause, for several reasons. First, I suspect 1000 is per process limit, not the per-session limit. In looking pages like http://www.cyberciti.biz/faq/linux-increase-the-maximum-number-of-open-files/ , it does look like Linux has per-session limit in addition to per-process limit, but 1000 for a whole session is too small. Plus, as the fork man page says, file descriptors are shared when a fork happens.
The second reason is, if hypothetically this is indeed the cause, then you'd likely see the fork fail. Other parts of the system should start exhibiting random "open" syscall failures.
When it happens the next time, I recommend attaching gdb and get the native stack dump. jstack is unlikely to work nor useful --- it's unlikely to work because between the fork and exec, JVM is in a very wierd state where, as forked child process only has one thread, and that VM has lost all the other threads that are critical to the health of JVM (such as GC thread, hotspot compiler thread, etc.) Responding to jstack requires a functioning JVM.
It's also unlikely to be useful because the code between the fork and exec is entirely in the native code. So we need gdb and get where in the native code it's stuck.
I'm really looking forward to learning the root cause for this.
On the point of having a helper process to deal with this.
ReplyDeleteThe short answer is that it's already done, and that's called slaves.
Now here's the long answer.
As discussed in the link Henk mentioned, Solaris requires that there be enough swap space to back up the entire memory usage of the forked process. That is, if your Jenkins weighs at 4GB, Solaris wants another 4GB of real/swap memory, even though it doesn't use it, or else the fork fails with "OutOfMemoryError: out of swap space?" I used to think this is silly, because forked processes share most of the pages thanks to COW, and so long as it execs right away, it wouldn't ever use another 4GB. So when I run my Jenkins on Solaris, I gave it pretty big swap space to avoid this problem.
On Linux, this is not the case. It lets the fork succeed without requiring the swap space to back up the process memory space currently in use. Plus, it's not like Jenkins forks processes all that frequently --- I think we are talking about one in a second, maybe --- I don't think it's a real problem.
I knew these based on the experience and observation, but
http://developers.sun.com/solaris/articles/subprocess/subprocess.html that Hank provided goes into a lot of background that I didn't know before. It's a fascinating read. Thanks for that pointer.
We had a similar problem on an Ubuntu Desktop box, switching to Debian Server resolved the issue. We didn't know why but ulimit -n on Ubuntu is 1024 and more than 308000 on the debian server.
ReplyDeleteI found this issue again today. I strace'ing the process hung again, and gdb complained "Attaching
ReplyDeleteptrace: Operation not permitted." even though ran it as root.
However, I did capture the stack:
[] xfs_trans_alloc+0x55/0xb0
[] xfs_free_eofblocks+0xec/0x200
[] xfs_release+0x133/0x260
[] xfs_file_release+0x10/0x20
[] fput+0xe2/0x220
[] filp_close+0x61/0x90
[] sys_close+0x92/0xf0
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff
Also from /proc/../status:
State: D (disk sleep)