Why MySQL using 98% of its CPU time on native class SocketInputStream?

[imagineer77]

System: AMD Althlon 1Ghz with 512Mb RAM 20Gb IDE HD
OS: Linux 2.4.7-10 (Red Hat 7.x)
Language: Java 1.4.1-01
MySQL: Ver 11.18 Distrib 3.23.52 Max
JDBC: mysql-connector-java-3.0.1-beta (was using mm.mysql-2.0.14)

I am running MySQL and import codes written in Java within the same server. The codes use PreparedStatements. This import would read from a flat file and each row of record would be inserted or updated into 7 tables. These tables have very small amount of records (less than 100,000 rows.)
It is taking about 0.65 second to process one row of import data. I think which is very slow.

While the import is running:

Mysqld uses up 88.9% CPU time and 33.8% memory.
The import code uses up only 0.4% CPU time and 11.8% memory.

I also profiled the import codes. The java.net.SocketInputStream.socketRead0 native (stub) method is consuming 98.2% of the run time. Also note that the java.net.SocketInputStream.socketRead0 native (interpreted) method is only consuming 1.5% of the run time. Somehow, the JVM is sleeping a lot and waiting for the stub (remote) class SocketInputStream to execute the stub (remote) socketRead method. Question is: Does this particular JDBC driver (or in general) somehow using something like RMI to talk to MySQL server? That could not be true, right? However, based on my browsing on org.gjt.mm.mysql.MySQLIO.java (mm.mysql-2.0.14), this might be the only place that this JDBC API creates and uses a socket connection, it is relatively straight forward.

If you have any suggestion or idea, please feel free to email me direct at jimmy.chong@benefitresourceinc.com. Thanks ahead. I will be very appreciated.

Also, would this issue directly or indirectly related to what happened with thread436-386910?

System recourse usage:

109 processes: 106 sleeping, 3 running, 0 zombie, 0 stopped
CPU states: 80.2% user, 19.5% system, 0.1% nice, 0.0% idle
Mem: 513308K av, 507340K used, 5968K free, 72K shrd, 8060K buff
Swap: 1044184K av, 3280K used, 1040904K free 89764K cached

PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
26433 mysql 18 0 172M 169M 2580 R 88.9 33.8 33:17 mysqld
1232 root 10 0 5808 5804 1436 S 8.2 1.1 20:59 Xvnc
25958 root 19 19 7120 7112 5716 R N 0.3 1.3 1:42 kspace.kss
26421 root 9 0 30460 29M 17008 S 0.3 5.9 0:10 java
26426 root 9 0 30460 29M 17008 S 0.1 5.9 0:03 java
1 root 8 0 520 520 452 S 0.0 0.1 0:06 init


Complete Java profile listing:

Flat profile of 3655.59 secs (181893 total ticks): main

Interpreted + native Method
1.5% 0 + 2710 java.net.SocketInputStream.socketRead0
0.0% 7 + 0 com.bri.database.dataimport.ContactImporter.updateEmployeeUserPhoneRecords
0.0% 4 + 0 com.bri.database.dataimport.ContactImporter.getPersonalInfoId
0.0% 4 + 0 com.bri.database.dataimport.ContactImporter.loadEmployee
0.0% 0 + 2 java.net.SocketOutputStream.socketWrite0
0.0% 0 + 2 java.util.zip.ZipFile.read
0.0% 2 + 0 com.bri.database.dataimport.ContactImporter.getUserAddressId
0.0% 1 + 1 java.net.URL.<init>
0.0% 1 + 0 java.lang.Object.clone
0.0% 0 + 1 java.util.TimeZone.getSystemTimeZoneID
0.0% 0 + 1 java.io.UnixFileSystem.getLength
0.0% 0 + 1 java.lang.ClassLoader$NativeLibrary.load
0.0% 0 + 1 java.lang.Class.getDeclaredConstructors0
0.0% 0 + 1 java.lang.ClassLoader.findBootstrapClass
0.0% 0 + 1 java.lang.Class.forName0
0.0% 0 + 1 java.util.zip.ZipFile.getEntry
0.0% 0 + 1 java.util.zip.Inflater.inflateBytes
0.0% 0 + 1 java.util.zip.ZipFile.freeEntry
0.0% 1 + 0 java.io.BufferedReader.readLine
0.0% 0 + 1 java.io.FileInputStream.readBytes
0.0% 0 + 1 java.util.jar.JarFile$JarFileEntry.<init>
0.0% 1 + 0 java.util.regex.Pattern.matcher
0.0% 0 + 1 java.util.zip.ZipFile.getInputStream
0.0% 1 + 0 java.util.regex.Matcher.getTextLength
0.0% 1 + 0 java.util.regex.Pattern.compile
1.5% 46 + 2755 Total interpreted (including elided)

Compiled + native Method
0.0% 12 + 0 java.math.BigInteger.mulAdd
0.0% 9 + 0 java.lang.String.toUpperCase
0.0% 9 + 0 org.gjt.mm.mysql.PreparedStatement.executeUpdate
0.0% 8 + 0 java.lang.StringCoding.decode
0.0% 7 + 0 org.gjt.mm.mysql.PreparedStatement.set
0.0% 7 + 0 org.gjt.mm.mysql.PreparedStatement.executeQuery
0.0% 6 + 0 java.lang.String.equals
0.0% 6 + 0 java.lang.StringCoding$CharsetSD.decode
0.0% 6 + 0 java.util.Locale.getDefault
0.0% 6 + 0 org.gjt.mm.mysql.MysqlIO.sqlQueryDirect
0.0% 4 + 1 java.lang.System.getProperty
0.0% 5 + 0 java.lang.String.hashCode
0.0% 5 + 0 java.lang.Integer.toString
0.0% 4 + 0 vtable chunks
0.0% 4 + 0 java.lang.StringBuffer.append
0.0% 4 + 0 org.gjt.mm.mysql.PreparedStatement.setString
0.0% 4 + 0 org.gjt.mm.mysql.MysqlIO.readPacket
0.0% 4 + 0 java.io.BufferedInputStream.fill
0.0% 3 + 0 java.io.BufferedInputStream.<init>
0.0% 3 + 0 java.lang.String.<init>
0.0% 3 + 0 java.lang.StringBuffer.expandCapacity
0.0% 3 + 0 org.gjt.mm.mysql.Buffer.readLenString
0.0% 3 + 0 java.util.Hashtable.<init>
0.0% 3 + 0 org.gjt.mm.mysql.Field.<init>
0.0% 3 + 0 java.util.Hashtable.put
0.1% 230 + 3 Total compiled (including elided)

Stub + native Method
98.2% 0 + 178604 java.net.SocketInputStream.socketRead0
0.1% 0 + 98 java.security.AccessController.doPrivileged
0.0% 2 + 60 java.net.SocketOutputStream.socketWrite0
0.0% 0 + 24 java.net.PlainSocketImpl.socketAvailable
0.0% 1 + 8 java.lang.System.currentTimeMillis
0.0% 0 + 3 java.util.zip.ZipFile.read
0.0% 0 + 2 java.util.zip.ZipEntry.initFields
0.0% 0 + 2 java.util.zip.ZipFile.getEntry
0.0% 0 + 1 java.util.zip.ZipFile.getMethod
0.0% 0 + 1 java.util.zip.ZipFile.getNextEntry
98.3% 3 + 178803 Total stub

Runtime stub + native Method
0.0% 1 + 0 ldiv_stub Runtime1 stub
0.0% 1 + 0 Total runtime stubs

Thread-local ticks:
0.0% 4 Class loader
0.0% 3 Interpreter
0.0% 16 Compilation
0.0% 23 Unknown: running frame
0.0% 6 Unknown: thread_state

Global summary of 3655.59 seconds:
100.0% 181912 Received ticks
0.0% 16 Received GC ticks
0.0% 33 Compilation
0.0% 3 Other VM operations
0.0% 4 Class loader
0.0% 3 Interpreter
0.0% 29 Unknown code

 

[imagineer77]

Thank you for reading this thread.

I have found the reason and I would like to update my finding here. It is not my Java code. It is not the MySQL database. The problem is with the network connection between my local machine and the database server. Although, I am running the java codes and MySQL on the same machine but I ssh from my local machine to the database server which creates all the trouble. I ran the same code on another machine and it took only 0.044 second to process one row from the flat file. The result is 15 times faster. I think I need to check my local network hub and network cables to see if any of them are faulty ones. Thanks.