VisualVM socket.read

Question

So I was profiling my application with VisualVM.

I hit a hotspot about my MySQL interaction. My first thoughts was that hot spot was showing time that my application was waiting after the IO. But in the profiling report, VisualVM has two column "Time" and "Time (cpu)". Maybe the term is wrongly used, but I assumed self-time (cpu) column was excluding IO time. After more debugging, we concluded that assumption was wrong and was showing IO time because the hotspot was on java.net.SocketInputStream.read() of the MySQL driver and other IO things that should not cost any cpu.

So, my question is why visualvm report SocketInputStream.read() as cpu time?

Answer 1

native calls are always in the RUNNABLE state while monitoring thread activity, probably because the JVM has no way to know if the native call is sleeping or actually doing something. Thus, time passed in the RUNNABLE state counts as CPU time.

Answer 2

This very long thread claims that small writes could be causing the problem. It is worth a read, but I don't know what you could do about it. What could you do? You might make sure you aren't using a small fetch size. This wouldn't give you small writes, but small reads which leads to the same problem. You might try different platforms for the client or server. There is a comment in this bug that reads:

"We've seen vastly different behavior on how quickly I/O buffers get filled between Solaris and Linux (and thus the number of calls to ReadAheadInputStream.fill(), because it reads what's available, it doesn't block unless it needs to read more than what's available)."