weird Java performance on linux server

[John Matthews]

2 company servers on which I can build my (relatively simple) app using javac. On one, it always takes under 2 seconds. On the other, ~30% of the builds take longer - 20% are 2-3 seconds, 7% are 3-4 seconds, and the remainder are longer.

(I see similar behavior when running the app, hence I believe it's a general java problem rather than something specific to javac.)

I'm using the linux/gnu 'time' command to investigate this, and including the CPU percentage (%P) in the output. I could understand it if the 'slow' builds had lower CPU% values, but they don't - the 'quick' <2 second builds are typically 200-250%, but the >7 second build I recorded earlier had a CPU usage of 1000%.

So if there's a resource conflict with one or more other processes, it doesn't appear to be lack of CPU that's the problem. And if it's something else, why doesn't java/javac just idle until it becomes available? Is it busy-waiting?

Any insights gratefully received. If it helps, java -version = 1.7.0_85; linux 2.6.32 (uname reports 'GNU/Linux'). From my perspective, the servers are 'the same' - just a change in the last digit of the address I ssh to.

Cheers
John

[Joe Ess]

Is the full output from java -version identical?  I used to see a significant performance penalty when I used OpenJDK installed by default on a lot of Linux distributions.  I think it has gotten better in recent years, but I always install the Oracle JDK just in case.  

[Stephan van Hulst]

So the servers have the same hardware, the same services running, the same configuration, etc?

How do the servers access the code that needs to be built?

[John Matthews]

Thanks for the replies.

Is the full output from java -version identical?

Yes (checked with tkdiff). Both reporrt:

java version "1.7.0_85"
OpenJDK Runtime Environment (rhel-2.6.1.3.el6_6-x86_64 u85-b01)
OpenJDK 64-Bit Server VM (build 24.85-b03, mixed mode)

So the servers have the same hardware, the same services running, the same configuration, etc?

I'm afraid I don't know; they 'feel' the same, but I appreciate that doesn't mean much. I have asked our IT department if they can throw any light on what's going on, and I would hope they would have told me if there were any significant differences that might explain it. Anything in particular I should check (and how)?

How do the servers access the code that needs to be built?

Sorry, not sure what you mean. That is, the code appears as files in the linux file system, but I suspect you're look for more detail than that which I probably won't be able to provide you with (unless you tell me which commands to enter).

Cheers
John

[Joe Ess]

John Matthews wrote:Thanks for the replies.

java version "1.7.0_85"
OpenJDK Runtime Environment (rhel-2.6.1.3.el6_6-x86_64 u85-b01)
OpenJDK 64-Bit Server VM (build 24.85-b03, mixed mode)

As I said, the Oracle JDK may give you better performance across the board.  

I'm afraid I don't know; they 'feel' the same

Definitely follow up with IT to see if there's any differences between the systems. That would be a very likely cause. I've also used benchmark programs like DeCapo to look at (close to) real-world performance of my servers.

Sorry, not sure what you mean.  

I think Stephan wants to know if you are using a source control system to manage your code or if you manage the source by hand.  If you aren't using source control, it's possible that you have file variations between your systems that will be difficult to identify.

[John Matthews]

As I said, the Oracle JDK may give you better performance across the board.

I think the only way I could attempt to change that would be to put a request in to IT, and I don't rate my chances.

I've also used benchmark programs like DeCapo to look at (close to) real-world performance of my servers.

Ok, I'll try that later. But I can't control what other users (on other continents) are doing on those servers, which I guess is going to affect those benchmark results?

If you aren't using source control, it's possible that you have file variations between your systems that will be difficult to identify.

The source is in git, but I don't think that's relevant here - the servers see the same filesystem as far as the directories where I'm working are concerned. That is, if I'm working on one server and make a change to a file, I see that change immediately in (what appears to be) the same file at the same filesystem location on the other server.

Cheers
John

[Stephan van Hulst]

That, or if the source is accessed from a repository that's not on those servers, network latency may also be a factor.

[Stephan van Hulst]

John Matthews wrote:That is, if I'm working on one server and make a change to a file, I see that change immediately in (what appears to be) the same file at the same filesystem location on the other server.

It matters though. A file system is just an abstraction. Even if both servers "see" the same thing, the physical location may influence compilation times.

[John Matthews]

Stephan van Hulst wrote:

John Matthews wrote:That is, if I'm working on one server and make a change to a file, I see that change immediately in (what appears to be) the same file at the same filesystem location on the other server.

It matters though. A file system is just an abstraction. Even if both servers "see" the same thing, the physical location may influence compilation times.

Yes, that makes sense. But would you expect to see high CPU usage while Java is waiting for the network? I would expect slow compilation with low CPU usage, not high.

[John Matthews]

John Matthews wrote:I would expect slow compilation with low CPU usage, not high.

(if the slow compilation is caused by network latency)

[John Matthews]

Regarding hardware differences, I've just done lscpu. The server where I see the slow builds 'only' has 24 'CPUs' compared to the other's 40, and 12288K L3 cache vs 25666K. But if these differences were the cause of different build times, wouldn't the symptoms be consistent? For 'normal' builds, the times are pretty similar; it's only the odd build on the one server that's slow.

[Tim Holloway]

John Matthews wrote:the >7 second build I recorded earlier had a CPU usage of 1000%.

Alarm bells.

Actually, even the 250% number is disturbing. Compiling used to be a big system load, but that was back when computers were less powerful than today's cellphones.

Actually compilers tend to be more I/O bound than CPU bound.

For that much CPU overhead, I'd check the paging rates. Virtual swaps eat a surprising amount of CPU. Use vmstat to monitor.

Also, my own experience for good performance is that you want the compiler task and the files being compiled on the same machine.

[John Matthews]

Tim Holloway wrote:For that much CPU overhead, I'd check the paging rates. Virtual swaps eat a surprising amount of CPU. Use vmstat to monitor.

Thanks Tim - just to confirm, that's something that's going to change significantly from build to build, resulting in orders of magnitude differences in build times and CPU usage?

Using top, I didn't see big changes in other activity on the server(s) while recording my results, but that's not to say there weren't any.

[John Matthews]

...and sorry, how should I use vmstat?

[Tim Holloway]

John Matthews wrote:...and sorry, how should I use vmstat?

vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 294436   2068 630292    0    0   110   328  223  164  5  3 90  2  0

The "so" is swap out rate, si is swap in, swpd is pages swapped and "man vmstat" has detailed info.

Ideally, you're not swapping at all. The higher the swap rate, the less efficiently you're using memory and you probably need to either offload something or IBM it (Install Bigger Memory).

You can set vmstat to periodically sample and print, which gives an ongoing view.

[John Matthews]

Right - some more data for you

Results of timing some (clean) builds earlier. The time command I'm using is
/usr/bin/time -f "real=%e user=%U sys=%S %%=%P flt=%F ctx=%c wait=%w in=%I out=%O"
but I also did a 'date' before the build, and have prefixed time output lines with timestamps (and added a load of spaces to make the columns line up):

00:57:18 real= 1.51 user=  3.57 sys=  0.11 %= 244% flt=0 ctx=   85 wait= 1393 in= 88 out=1112
00:57:21 real= 1.54 user=  3.43 sys=  0.10 %= 229% flt=0 ctx= 1190 wait= 1365 in= 88 out=1112
00:57:23 real=42.95 user=146.18 sys=241.94 %= 903% flt=0 ctx=98364 wait= 7348 in= 88 out=1152
00:58:07 real= 1.46 user=  3.17 sys=  0.10 %= 223% flt=0 ctx=  733 wait= 1338 in= 88 out=1112
00:58:10 real= 1.52 user=  3.44 sys=  0.11 %= 234% flt=0 ctx= 1186 wait= 1350 in= 88 out=1112
00:58:12 real= 1.50 user=  3.43 sys=  0.11 %= 236% flt=0 ctx= 1208 wait= 1255 in= 88 out=1112
00:58:15 real= 1.50 user=  3.48 sys=  0.12 %= 240% flt=0 ctx=   82 wait= 1413 in= 88 out=1112
00:58:18 real= 1.49 user=  3.47 sys=  0.11 %= 239% flt=0 ctx=  682 wait= 1224 in= 88 out=1112
00:58:20 real=56.97 user=407.65 sys=169.20 %=1012% flt=0 ctx=47475 wait=15762 in= 88 out=1168
00:59:18 real=20.76 user=160.59 sys= 32.15 %= 928% flt=0 ctx=72420 wait= 6704 in= 88 out=1112
00:59:40 real=15.64 user=192.58 sys= 57.85 %=1600% flt=0 ctx=12897 wait= 8053 in= 88 out=1112
00:59:56 real=12.24 user=165.22 sys= 23.95 %=1544% flt=0 ctx=26765 wait= 6731 in= 88 out=1112
01:00:10 real= 1.49 user=  3.61 sys=  0.11 %= 248% flt=0 ctx=  565 wait= 1236 in= 88 out=1112
01:00:12 real= 1.57 user=  3.62 sys=  0.13 %= 238% flt=0 ctx= 1482 wait= 1252 in= 88 out=1112
01:00:15 real=14.14 user=  3.19 sys= 12.76 %= 112% flt=0 ctx=  772 wait= 1553 in= 88 out=1112
01:00:30 real= 1.51 user=  3.41 sys=  0.11 %= 232% flt=0 ctx=  502 wait= 1429 in= 88 out=1112
01:00:33 real= 1.47 user=  3.19 sys=  0.09 %= 222% flt=0 ctx=  800 wait= 1289 in= 88 out=1112
01:00:35 real=22.41 user=170.71 sys= 42.19 %= 949% flt=0 ctx=70862 wait= 7530 in= 88 out=1112
01:00:58 real= 1.52 user=  3.58 sys=  0.14 %= 244% flt=0 ctx=   99 wait= 1222 in= 88 out=1112
01:01:01 real= 1.68 user=  3.37 sys=  0.11 %= 207% flt=0 ctx= 1099 wait= 1293 in= 88 out=1112
01:01:04 real= 1.50 user=  3.53 sys=  0.11 %= 242% flt=0 ctx=   72 wait= 1248 in= 88 out=1112
01:01:06 real= 1.51 user=  3.49 sys=  0.13 %= 239% flt=0 ctx=   84 wait= 1299 in= 88 out=1112
01:01:09 real=25.94 user=198.48 sys= 27.65 %= 871% flt=0 ctx=26777 wait= 8527 in= 88 out=1112

You can see how the times vary, and long times correspond to high CPU%. I was also running vmstat in a background process, with timestamps; here is its output around the first long build time (real=42.95, starts at 57:23) including 'normal' builds before and after. Timestamps are on the ends of the lines.

procs -----------memory----------       ---swap-- -----io---- --system-- -----cpu------ ---timestamp---
 r  b     swpd     free   buff    cache   si   so    bi    bo      in    cs us sy id wa st
 4  0 76333544 43970656 590452 16605216    0    0     0     0    7445  2861 19  2 79  0  0 00:57:20
 6  0 76333544 43943044 590452 16605184    0    0     0     0    7533  3649 19  2 80  0  0 00:57:21
 4  0 76333544 43972048 590460 16605208    0    0     0   340    9699  5124 26  2 72  0  0 00:57:22
 6  0 76333544 43968680 590460 16605176    0    0     0     0    8945  4949 16  2 82  0  0 00:57:23
 5  0 76333544 43955248 590460 16605184    0    0     0     0  486956  2977 16  5 79  0  0 00:57:24
 5  0 76333536 43954068 590460 16605220    8    0     8     0  604118  3442 15  6 78  0  0 00:57:25
 5  0 76333536 43961624 590460 16605224    0    0     0     0  527548  2384 16  5 79  0  0 00:57:26
 5  0 76333536 43965376 590460 16605216    0    0     0    36  659432  2432 16  5 79  0  0 00:57:27
 5  0 76333536 43966676 590468 16605208    0    0     0   108  582570  2209 16  5 79  0  0 00:57:28
 5  0 76333536 43963832 590468 16605216    0    0     0     0  636109  2549 16  5 78  0  0 00:57:29
 5  0 76333536 43962964 590468 16605216    0    0     0    48  701184  2147 16  5 79  0  0 00:57:30
 5  0 76333536 43964220 590468 16605216    0    0     0     0  645586  2233 16  5 79  0  0 00:57:31
 5  0 76333536 43963260 590468 16605216    0    0     0   196  559352  2264 16  5 79  0  0 00:57:32
 5  0 76333536 43964220 590468 16605216    0    0     0     0  507573  4276 16  6 79  0  0 00:57:33
 5  0 76333536 43961428 590468 16605216    0    0     0     0  525906  5093 17  5 78  0  0 00:57:34
 6  0 76333528 43960556 590468 16605212    8    0     8     0  618576  2785 16  5 79  0  0 00:57:35
 5  0 76333528 43961912 590468 16605216    0    0     0     0  644466  3316 16  5 79  0  0 00:57:36
 6  0 76333520 43961932 590468 16605216    0    0     0     0  594211  2192 17  4 79  0  0 00:57:37
 5  0 76333512 43960608 590468 16605208   16    0    16     0  642993  2241 16  5 79  0  0 00:57:38
 6  0 76333512 43960420 590468 16605216    0    0     0     0  727927  2240 17  4 79  0  0 00:57:39
 5  0 76333512 43960420 590468 16605216    0    0     0    40  651857  2164 17  5 79  0  0 00:57:40
 5  0 76333512 43960484 590468 16605216    0    0     0     0  556639  2252 17  4 79  0  0 00:57:41
 5  0 76333512 43960296 590468 16605216    0    0     0    16  543026  2301 16  5 79  0  0 00:57:42
22  0 76333512 43933216 590468 16605216    0    0     0     0  665883 14649 30 24 46  0  0 00:57:43
23  0 76333512 43925204 590468 16605216    0    0     0     0 1165017 19029 39 46 15  0  0 00:57:44
22  0 76333512 43926680 590468 16605216    0    0     0     0 1186447 16485 40 47 13  0  0 00:57:45
22  0 76333512 43924484 590468 16605216    0    0     0     0 1152964 14499 40 47 13  0  0 00:57:46
22  0 76333512 43924616 590468 16605216    0    0     0     0  917303 12113 41 46 13  0  0 00:57:47
22  0 76333512 43925436 590476 16605208    0    0     0    12  700796 14291 41 46 13  0  0 00:57:48
21  0 76333512 43921576 590476 16605216    0    0     0     0  976316 12665 41 46 13  0  0 00:57:49
22  0 76333512 43920636 590476 16605216    0    0     0     0  830197  4715 43 47 10  0  0 00:57:50
22  0 76333512 43917332 590476 16605216    0    0     0     0  789856  2930 44 47  9  0  0 00:57:51
22  0 76333512 43916824 590476 16605216    0    0     0   176  800232  3204 44 47  9  0  0 00:57:52
21  0 76333512 43917788 590476 16605220    0    0     0     0  885130  4371 44 47  9  0  0 00:57:53
22  0 76333512 43915260 590480 16605220    0    0     0    68 1103703  2923 43 47  9  0  0 00:57:54
22  0 76333424 43917708 590480 16605280   24    0    24     0 1362582  2950 42 48  9  0  0 00:57:55
22  0 76333424 43917792 590480 16605220    0    0     0     0 1580151  3051 44 47  9  0  0 00:57:56
22  0 76333424 43917912 590480 16605220    0    0     0    48 1555045  2872 44 46  9  0  0 00:57:57
22  0 76333424 43916376 590480 16605220    0    0     0     0 1196432  2840 44 47  9  0  0 00:57:58
22  0 76333424 43917012 590480 16605220    0    0     0     0 1115907  2858 44 47  9  0  0 00:57:59
20  0 76333424 43916440 590480 16605220    0    0     0     0  896762  3096 44 47  9  0  0 00:58:00
22  0 76333424 43916224 590488 16605216    0    0     0    32  504369  7212 44 47  9  0  0 00:58:01
16  0 76333424 43925600 590488 16605220    0    0     0    36 1131164  3111 44 25 30  0  0 00:58:02
14  0 76333424 43907740 590492 16605232    0    0     0    36 1414748  6478 45 18 37  0  0 00:58:03
14  0 76333424 43908024 590492 16605220    0    0     0     0 1204643  2882 43 18 39  0  0 00:58:04
12  0 76333424 43920132 590492 16605220    0    0     0     0  952391  2844 44 15 41  0  0 00:58:05
 4  0 76333424 43966336 590492 16605220    0    0     0     0   48136  5186 28  1 71  0  0 00:58:06
 5  0 76333424 43955892 590492 16605192    0    0     0     4    6143  2376 17  0 83  0  0 00:58:07
 7  0 76333424 43915056 590500 16605188    0    0     0    96   13223  8847 26  1 73  0  0 00:58:08
 4  0 76333424 43963340 590504 16605220    0    0     0   104    6797  2979 21  0 79  0  0 00:58:09
 7  0 76333424 43930716 590504 16605192    0    0     0     0    7600  3658 20  1 79  0  0 00:58:10
 4  0 76333376 43966028 590504 16605268    4    0     4     0    9779  5255 27  1 72  0  0 00:58:11

So in the long build vmstat shows that the 'in' value shoots up; in = 'the number of interrupts per second, including the clock'. And it looks more cores are brought in to handle the load(?).

So do you think the interrupts are the cause, or just a symptom? Any idea what they indicate?

[John Matthews]

John Matthews wrote:So in the long build vmstat shows that the 'in' value shoots up

...along with 'sy' = 'time spent running kernel code (system time)'.

[Tim Holloway]

You seem to have "bursty" events, possibly about every 30 seconds, although the sample size isn't large enough to be sure.

It's possible that there's some other process that kicks in at intervals and eats the machine, leaving little for the compiler process.

A crude way of checking this would be to run "top", although you might have to adjust its sampling interval to get a good idea. And of course, top itself is going to take periodic bites as it wakes up, samples, and displays.

[John Matthews]

Tim Holloway wrote:You seem to have "bursty" events, possibly about every 30 seconds

Sorry Tim - can you explain where you get that from?

It's possible that there's some other process that kicks in at intervals and eats the machine, leaving little for the compiler process.
A crude way of checking this would be to run "top", although you might have to adjust its sampling interval to get a good idea.

I have performed the tests while watching top and not noticed anything usual. This morning I suspect I was the only human user on the server.

Any suggestions as to what sort of process I should be looking for ie. what might cause all those interrupts?

[John Matthews]

Update - just re-run the build tests, and out of 96 builds, there were only 8 that took >2 seconds, and just one build took longer than 3 seconds. But they all had relatively low CPU% figures, which is what I would expect if something took longer than expected ie. they had to wait for some resource. So whatever was happening this morning isn't happening now.

[John Matthews]

John Matthews wrote:But they all had relatively low CPU% figures

'they' = the (slightly) longer builds

[Tim Holloway]

John Matthews wrote:

Tim Holloway wrote:You seem to have "bursty" events, possibly about every 30 seconds

Sorry Tim - can you explain where you get that from?

From looking at CPU usage down the table. It shows periods of low usage interrupted by periods of higher usage.

The "top" system utility can help pin down what's causing that.

[John Matthews]

Tim Holloway wrote:

John Matthews wrote:

Tim Holloway wrote:You seem to have "bursty" events, possibly about every 30 seconds

Sorry Tim - can you explain where you get that from?

From looking at CPU usage down the table. It shows periods of low usage interrupted by periods of higher usage.

But isn't that just my builds?

The "top" system utility can help pin down what's causing that.

I've just tried doing ps before each build to capture CPU usage. But after eliminating processes common to each (pre-)build, there wasn't anything left, at least in the top 35 I was recording (of which the last 4 or 5 measured 0% CPU).

As mentioned previously, I have watched top while the builds are going on and haven't spotted any difference in process activity between quick and slow builds.

I think the most promising line of inquiry is the interrupt activity recorded by vmstat; I'm going to have a look at /proc/interrupts...