I was involved in an interesting problem in the office recently. The problem is already documented in other posts such as:
Oracle 11g JDBC driver hangs blocked by /dev/random – entropy pool empty
Oracle JDBC Intermittent Connection Issue
MOS note “Adbldxml.pl Hangs After Upgrade To 11.2.0.3 (Doc ID 1585759.1)”
Essentially the problem is that /dev/random will block when there is insuffient entropy and JDBC uses /dev/random when negotiating a connection. I’ll not go back over information from the web pages above, please have a quick read of one of them.
What I wanted to do was demonstrate the issue using a Java program from the above MOS note and show evidence of the issue and delays. All the program does is connect to a database using a JDBC thin driver and “SELECT USER FROM dual”, I’ll run it three times as below:
time java oraConn & time java oraConn & time java oraConn &
and this is the output (“NJ” is my database account name):
NJ real 0m2.001s user 0m1.093s sys 0m0.094s NJ real 0m39.051s user 0m1.163s sys 0m0.089s NJ real 0m44.316s user 0m1.162s sys 0m0.087s
2 seconds for the first connection and 39 and 44 seconds for the others! Not good. We can use “strace” to find out what the processes are doing during these delays.
strace -t -o runjv1.trc -f java oraConn & strace -t -o runjv2.trc -f java oraConn & strace -t -o runjv3.trc -f java oraConn &
This is what I see in my strace output for one of the delayed sessions, repeated timeouts, many more than displayed below:
tail -f runjv1.trc
...
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 520708960}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 571177374}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 621626926}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 672072270}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 722524322}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 772872653}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
2755 21:02:02 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:02:02 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3390, 823298750}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
...
If I scroll up to the start of the block of timeouts I see this:
2734 21:01:30 read(15, <unfinished ...>
2755 21:01:30 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
2755 21:01:30 futex(0x7f1c440b1028, FUTEX_WAKE_PRIVATE, 1) = 0
2755 21:01:30 futex(0x7f1c440b1054, FUTEX_WAIT_BITSET_PRIVATE, 1, {3359, 26945244}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
We see the “read” on file descriptor 15 executed by PID 2734 on line 1 above. What are we reading from when reading descriptor 15? Further up the trace file we see:
2734 21:01:30 open("/dev/random", O_RDONLY) = 15
2734 21:01:30 fstat(15, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 8), ...}) = 0
2734 21:01:30 fcntl(15, F_GETFD) = 0
2734 21:01:30 fcntl(15, F_SETFD, FD_CLOEXEC) = 0
“/dev/random”! Nice, this agrees with the referenced posts.
We can monitor the available entropy by running this shell snippet during a re-test:
while [ 1 ];do date cat /proc/sys/kernel/random/entropy_avail sleep 1 done
And this is what we see, the available entropy drops causing reads on /dev/random to block. There are a few solutions in the referenced blog and MOS notes.
Wed Aug 19 21:28:07 BST 2015 161 Wed Aug 19 21:28:08 BST 2015 174 Wed Aug 19 21:28:09 BST 2015 134 Wed Aug 19 21:28:10 BST 2015 38 Wed Aug 19 21:28:11 BST 2015 50 Wed Aug 19 21:28:13 BST 2015 61 Wed Aug 19 21:28:14 BST 2015 62 Wed Aug 19 21:28:15 BST 2015 8 Wed Aug 19 21:28:16 BST 2015 21 Wed Aug 19 21:28:17 BST 2015 22 Wed Aug 19 21:28:18 BST 2015 35 Wed Aug 19 21:28:19 BST 2015 37 Wed Aug 19 21:28:20 BST 2015 49 Wed Aug 19 21:28:21 BST 2015 63 Wed Aug 19 21:28:22 BST 2015 0 Wed Aug 19 21:28:23 BST 2015 1 Wed Aug 19 21:28:24 BST 2015 17 Wed Aug 19 21:28:25 BST 2015 36 Wed Aug 19 21:28:26 BST 2015 37
I fully appreciate I am going over work covered by others but I thought the “strace” analysis added to other posts. Also it doesn’t hurt to highlight this issue again as I’m really surprised this is not more widely known as the use of virtual machines is so prevalent these days. I presume connection pools hide this from us most of the time.
ORAganism 