High CPU and load exploration when Java program starts

These two days to assist operations to locate 1 monitoring program CPU occupancy rate of 150%, the process twists and turns, the conclusion is simple, very interesting:)

First, let's look at the high CPU:

You can see the red box of the monitoring program CPU consumption is very high, but in fact, the implementation of these monitors is very simple: Send 1 HTTP requests, receive a response after a simple judgment of the response code, and then print the monitoring results, the print completed the exit. Each monitoring will be restarted by the daemon program.

Such a simple business occupies such a high CPU, how feel is not likely, so get the source of the monitoring program to start positioning.

The first thought is VISUALVM, jconsole and other tools , but because the program runs quickly completed, the two tools are not connected to the end, and the data can not see what the specific cause of the high CPU, give it up when you try it a bit.

The second attempt is to use Strace to track the call of the program , the result excerpt is as follows (omitted many) :

17572 14:08:43.485878 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.486132 clock_gettime (CLOCK_REALTIME, { 1423721323, 486165000}) = 017572 14:08:43.486204 Futex (0X580497A4, futex_wait_private, 1, {0, 9949000}) = 1 ETIMEDOUT (Co Nnection timed out) 17572 14:08:43.496964 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.497142 clock_gettime (Clock_realtime, {1423721323, 497169000}) = 017572 14:08:43.497236 Futex (0X580497A4, futex_wait_private, 1, {0, 9935000} ) =-1 Etimedout (Connection timed out) 17572 14:08:43.507896 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.50 8164 Clock_gettime (clock_realtime, {1423721323, 508201000}) = 017572 14:08:43.508240 Futex (0X580497A4, FUTEX_WAIT_  PRIVATE, 1, {0, 9945000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.518960 Futex (0x58049028, Futex_wake_private, 1) = 017572 14:08:43.519140 clock_gettime (clock_realtime, {1423721323, 519168000}) = 017572 14:08:43.519236 Futex (0x5804 97A4, Futex_wait_private, 1, {0, 9934000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.529882 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.5 30144 Clock_gettime (clock_realtime, {1423721323, 530177000}) = 017572 14:08:43.530216 Futex (0X580497A4, FUTEX_WAIT_  PRIVATE, 1, {0, 9946000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.540951 Futex (0x58049028, Futex_wake_private, 1) = 017572 14:08:43.541129 clock_gettime (clock_realtime, {1423721323, 541157000}) = 017572 14:08:43.541222 Futex (0x5804 97A4, Futex_wait_private, 1, {0, 9935000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.551872 Futex (0x58049028, FU Tex_wake_private, 1) = 017572 14:08:43.552127 clock_gettime (clock_realtime, {1423721323, 552159000}) = 017572 14:08:43.552199 Futex (0X580497A4, futex_wait_private, 1, {0, 9949000}) =-1 Etimedout (Connection timed out) 17572 14:08:43 .562857 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.563029 clock_gettime (clock_realtime, {1423721323, 563056000}) = 017572 14:08:43.563119 Futex (0x580497A4, Futex_wait_private, 1, {0, 9936000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.573913 Futex (0x58049028, FU Tex_wake_private, 1) = 017572 14:08:43.574159 clock_gettime (clock_realtime, {1423721323, 574214000}) = 017572 14:08:43.574253 Futex (0X580497A4, futex_wait_private, 1, {0, 9925000}) =-1 Etimedout (Connection timed out) 17572 14:08:43 .584885 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.585055 clock_gettime (clock_realtime, {1423721323, 585081000}) = 017572 14:08:43.585147 Futex (0X580497A4, futex_wait_private, 1, {0, 9936000}) = 1 etimedout (Connection Tim Ed out) 17572 14:08:43.595900 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.596170 clock_gettime (CLOCK_ REALTIME, {1423721323, 596206000}) = 017572 14:08:43.596245 Futex (0X580497A4, futex_wait_private, 1, {0, 9947000}) =-1 ET Imedout (Connection timed out) 17572 14:08:43.606960 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.607139 clo Ck_gettime (Clock_realtime, {1423721323, 607167000}) = 017572 14:08:43.607232 Futex (0X580497A4, futex_wait_private, 1, {0, 9935000}) = 1 etimedout (Connection timed out) 17 572 14:08:43.617875 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.618119 clock_gettime (CLOCK_REALTIME, { 1423721323, 618209000}) = 017572 14:08:43.618249 Futex (0X580497A4, futex_wait_private, 1, {0, 9890000}) = 1 ETIMEDOUT (Co Nnection timed out) 17572 14:08:43.628960 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.629140 clock_gettime (Clock_realtime, {1423721323, 629168000}) = 017572 14:08:43.629231 Futex (0X580497A4, futex_wait_private, 1, {0, 9935000} ) =-1 Etimedout (Connection timed out) 17572 14:08:43.639865 Futex (0x58049028, futex_wake_private, 1) = 017572 14:08:43.64 0134 Clock_gettime (clock_realtime, {1423721323, 640167000}) = 017572 14:08:43.640206 Futex (0X580497A4, FUTEX_WAIT_  PRIVATE, 1, {0, 9946000}) =-1 Etimedout (Connection timed out) 17572 14:08:43.650868 Futex (0x58049028, Futex_wake_private, 1) = 017572 14:08:43.651139 unlink ("/tmp/hsperfdata_gamedata/17559 ") = 017572 14:08:43.651324 exit_group (0) =?    

Why so many futex,google "Futex connection Time Out", hey, there are a lot of results, the most typical is leap second, Chinese translation for " leap second ", but look carefully, The last leap second occurred in June 2012, now 2015 years, and the CPU is high every day, it should not be the problem

The tool does not count on, had to look at the code, the code looked after a few places:

1) Countdownlatch: Because this is most likely to use the Futex, but actually think and verify, this stuff can not lead to CPU so high, really have this problem, this thing completely can't use

2) Multithreading: Look at the code, not a few threads, and the business is a round, it is not possible to multithreading caused

What if the problem is deadlocked? Had to use the ultimate big trick: segmented comment!

1) Comment Response processing code--No, CPU occupied 100%

2) Comment The code that sent the request--or not, CPU consumption 100%

This does not pit father, the request is not sent, the response is not, how can you be so slow?

3) Simply comment all the code, only in the main print Hello world--or not, CPU occupied 100%

This is the egg hurt, no business, your CPU is high, this does not pit me

4) Write a Hello world--, this time can be, CPU occupied 2%

The same goes for the print Hello World, why CPU difference is so big?

Wrestling, a sudden flash of light: Is it related to the JVM load class file?

when the JVM starts, it loads and connects all classes except reflection, and the class file is a binary file that needs to be loaded from disk to memory and parsed, which is CPU-intensive . The more class files, the higher the CPU cost, which explains why the same output Hello World, different program CPU occupancy varies greatly.

This inference also explains the phenomenon of another online project that was previously encountered: about 1 minutes after each boot, the CPU and load on the system were high, and it returned to normal after 1 minutes.

Recommendations

Need to repeat the operation of the Monitoring class program, if written in Java, it is best not to make every time to restart, but in the program inside the loop or timed operation;

If you have to restart every time, frequency is very frequent, it is recommended to use the shell, Python and other write, or a machine running too many Java Class tool program, will cause CPU and load soar

Reprint Please specify source: http://blog.csdn.net/yunhua_lee/article/details/43765371

High CPU and load exploration when Java program starts