19

While profiling homegrown web-application I came across following very strange (at least for me) observation.

Almost all time is spent in socketRead0() method of a SocketInputStream class. It's not surprising because my application do a networking with a remote service on each request. What is strange that not only wall clock time usage is high for this method, CPU clock time also very high. I can't understand why CPU time is high, because if my application wait for remote service to reply (which is not so fast in fact), there is nothing to do left for application itself. So CPU time should be apparently low.

Some more observation:

  • VisualVM in sampling mode shows that method SocketInputStream.socketRead0() is eating up to 95% of time (both wall clock time and CPU time);
  • mpstat (we use Linux as a OS) shows around ~90% user time and ~1-3% system time (the rest is idle time);
  • application deployed on the dedicated server;
  • remote service is HTTP web-application also. Average response time is about 100ms. Average response size is about 2Kb.
  • my application use spring RestTemplate to interact with remote service, not the SocketInputStream directly.

For now I have only one idea — maybe this is overhead of calling native methods in JVM (SocketInputStream.socketRead0() is native)?

What do you think? Is there any other reasons to this?

Adam Siemion
  • 15,569
  • 7
  • 58
  • 92
Denis Bazhenov
  • 9,680
  • 8
  • 43
  • 65
  • It seems a bit strange, but not impossible. Can you give more context? Does "homegrown web-application" play with sockets directly? Are you reading single bytes? – themel Sep 19 '12 at 06:15
  • Some more context under "Observations" – Denis Bazhenov Sep 19 '12 at 06:44
  • Do you have an idea of what's further up the stack or what the sizes of your reads are? I can imagine reaching your numbers if you e.g. tried to do JSON parsing from an unbuffered socket. – themel Sep 19 '12 at 08:57
  • @themel We are using Spring's RestTemplate, so we should be safe on that, I guess. But I'll check it. The average response size is about several kilobytes. – Denis Bazhenov Sep 19 '12 at 09:37
  • socketRead would be about request parsing, not responses (unless you're consuming someone else's services). – themel Sep 19 '12 at 10:15
  • See Brendan Gregg's in-depth post http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html – Jarek Przygódzki Aug 02 '19 at 12:37

2 Answers2

1

I am facing the same problem. My application has a very high qps and each request will make me send multiple thrift calls, which use this native api : socketRead0

So I decide to do an experiment. I make a mock server with an api sleep 30s before return and a client calls this api. My purpose is to test the thread status when the net io happening. Based on my thread dump, the thread status is RUNNABLE.

This explains to two things :

  1. application with high qps blocking io will face a high cpu load value

  2. your java thread is still running in jvm since the thread state is RUNNABLE which will contribute to high user space cpu utilization

both of these will make your cpu busy.

I noticed during the experiment, the system space cpu utilization is low. I think this something relates to the thread scheduling strategy difference between jvm and os. We know hotspot threading model is 1:1, meaning one jvm thread to one os thread. when a blocking io happened, such as socketRead0 the kernel thread will set to state S and will not blocking cpu, but user space thread is blocking(waiting). when this happened, I think we need to rethink the fundamental I/O model in our application.

hakunami
  • 2,351
  • 4
  • 31
  • 50
  • 3
    This phenomenon explained in http://stackoverflow.com/questions/20475290/why-does-select-consume-so-much-cpu-time-in-my-program?noredirect=1&lq=1 – Denis Bazhenov Apr 27 '17 at 04:50
  • What @DenisBazhenov is trying to say is, 100% CPU in this case is the sum of the program itself, not the sum of the CPU as a whole. So if your program is taking 5% CPU, and 99% is spent in socketRead, that means that your program is spending 99% of its time in the socketRead function in a program that is only taking 5% CPU, which probably isn't from the socket anyways. So better not call Sleep( ) or that might start taking 100%. – Brain2000 Dec 20 '17 at 21:12
0

VisualVM shows load not as an absolute value but as a relative value, so it simply means that your application does not have any more CPU-consuming point.

I believe you should configure VisualVM to not drill that deep down, and rather count this method call as part of a method that is in your code (or spring's).

I have already experienced such a behaviour, but it didn't look like it was requiring any optimization. The Web Application simply has to read data from sockets (i.e. HTTP Request, database, internal network services...) and there is no helping it.

mauhiz
  • 506
  • 5
  • 14