jmeter icon indicating copy to clipboard operation
jmeter copied to clipboard

Jdbc poor performance

Open asfimport opened this issue 3 years ago • 10 comments

feng (Bug 66050): Hi, I am testing a database called dolphindb with jmeter.I start 100threads for 2 server.The testing result was: throughput 6.9/sec . The sql query like this : select timestamp,value from ... where system_code = 'system_1882' and device_id = 'device_4' and metric = 'metric_9' and timestamp >= 2021.05.01T00:00:00.000 and timestamp <= 2021.05.31T23:59:59.999

But i write a program with same dolphindb_jdbc.jar to test, same 100 threads, same testing for 1minute, same servers , i got at least 1000 query per thread . I don't know why the difference so big . I collect some infomation and try some methods ,still didnt work.

Jmeter run in single mode .Running on a Linux server. This server has 3 network cards. One can reach 10000Mb/s, the others only for 1000Mb/s . At first ,i thought the jmeter use the wrong network cards.So here is my effort: modify jmeter: add : rmi_host="-Djava.rmi.server.hostname=192.192.168.1" then modify : ARGS="$JAVA9_OPTS $SERVER $DUMP $HEAP $VERBOSE_GC $GC_ALGO $SYSTEM_PROPS $JMETER_LANGUAGE $RUN_IN_DOCKER $rmi_host" modify jmeter.properties: remote_hosts=192.192.168.1 【192.192.168.1 is Intranet address】 modify system.properties: add :java.rmi.server.hostname=192.192.168.1

Didn't work.Then i testing with my program , observe with command dstat (which can Monitor the overall performance of the server) . I got the max recv 250MB/s . but with Jmeter , sometimes the net recv reachs 140Mb/s, most time less then 10mb/s .

Then it reminds me : The server needs to go through vpn to connect to the external network, and the speed is the max 10mb/s . And i used external net to access my server and run jmeter. But i already modify the host,did i miss something ?

I chaned the query sql ,new sql like: select min(value) from ... where system_code = 'system_1882' and device_id = 'device_4' and metric = 'metric_9' and timestamp >= 2021.05.01T00:00:00.000 and timestamp <= 2021.05.31T23:59:59.999 It returns less rows than previous sql .Well,the tesing results are very good : throughput 3000/sec .

I modify the dolphin_jdbc.jar ,debuging the query time. Well ,the testing results shows ,for different sql, the query time is similar. So i don't think it's the dolphin_jdbc.jar problem , so i thought it might be there was some problems getting too much results . So i disable the results tree in jmeter , and modify jmeter.properties: jmeter.save.saveservice.response_message=false jmeter.save.saveservice.successful=false Still didn't work.

I have already done my best and i'm desperate.Hope to get some help. By the way , i'm praticing english , hope my description is accurate

Created attachment Java_Formal.jmx: jmx_file

Severity: blocker OS: Linux

asfimport avatar May 04 '22 14:05 asfimport

feng (migrated from Bugzilla): JDBCPrepareStatement.JDBCPrepareStatement(JDBCConnection connection, String sql) take time: 386267 JDBCPrepareStatement.createSql() take time: 2031 DBCPrepareStatement.close() take time: 6498

the unit is ns

JDBCPrepareStatement.executeQuery() take time: 497 the unit is ms

first few query costs less then 500ms ; then the next query costs less then 50ms. The log shows this

Created attachment 2.log: jdbc.jar debug log

asfimport avatar May 04 '22 14:05 asfimport

@FSchumacher (migrated from Bugzilla): I think this is probably a question for the users mailing list, but anyways.

  1. Why are you using prepared statements without parameters? I think you will store quite a few prepared statements in your cache, without re-using them. Is this intended?

  2. Can you post your Java sample? Is it running from the same host as the JMeter script?

  3. Take a few thread dumps while the script is running (and seems slow), that might give us a better view into the problems

  4. Enable gc-logging and take a look (post them here) into them, is the script slow because of GC?

  5. You might want to enable JFR or an async profiler to get better insight to where the problems really are hidden

  6. Have you tried to set the pool size to "0" (i.e. disabling the pool)?

  7. Don't control the JMeter workers over a small LAN connection, it will be a bottleneck. Run the control server and the workers in a network, that has good bandwidth.

asfimport avatar May 04 '22 15:05 asfimport

feng (migrated from Bugzilla): To Felix Schumacher: First of all,thanks for your reply.I took your advice and make some changes: 1.There are historical reasons for using prepared statements,but anyway , i changed to select statement and follow your 6th and 7th advice. I put Jmeter on the intranet,set the pool size to "0",using select statement, and the problem remains.

2.I collect a few thread dumps,gc-log,async profiler while the script is running: It seems its been blocked by AbstractJdbcTestElement.getStringFromResult Is that mean ,the dolphindb_jdbc.jar is very inefficient in parsing data. Is there any way i can avoid this . like : not parsing data or parsing data won't block the query thread?

Well,maybe i can change sql into : select count(*) from (select timestamp,value from ..) but this goes against my needs in the first place

3.I don't program with java sampler.I just make a runnable java program which support to start multiple threads to query continuously for 1 minute. In my code , i don't parse the data, just query. The core code like this :

        long runningtime = System.currentTimeMillis()+minute*60*1000;
        
        long begintime = System.currentTimeMillis();
        do {
        	
        	count++;
        	try {
                    // genarate a random sql                         
        		sql = createSql.genSql();
        		long b = System.currentTimeMillis();
        		PreparedStatement stmt = conn.prepareStatement(sql);
        		ResultSet rs = stmt.executeQuery();
        		long c = System.currentTimeMillis();
                    System.out.println("cost:"+(c-b));
            }catch ...
         } while (System.currentTimeMillis()&lt;runningtime);

I have upload the logs , dumps , async profile。 Looking forward to your reply. Thanks !

asfimport avatar May 05 '22 15:05 asfimport

feng (migrated from Bugzilla): Created attachment jmeter.zip: dumps,logs,profile

asfimport avatar May 05 '22 15:05 asfimport

@FSchumacher (migrated from Bugzilla): Thanks for the information, especially the thread dump shows a probable candidate for your problems. The JDBC driver has trouble to format the numbers to string under high thread load. Most of the threads are waiting like the following:

"node2 2-39" #122 prio=5 os_prio=0 tid=0x00007fa8bc2dc000 nid=0x4479e waiting for monitor entry [0x00007fa8092d1000] java.lang.Thread.State: BLOCKED (on object monitor) at java.text.DecimalFormat.format(DecimalFormat.java:615) - waiting to lock <0x00000005e4768f68> (a java.text.DigitList) at java.text.DecimalFormat.format(DecimalFormat.java:544) at java.text.NumberFormat.format(NumberFormat.java:296) at com.xxdb.data.BasicDouble.getString(BasicDouble.java:76) at com.xxdb.data.AbstractScalar.toString(AbstractScalar.java:33) at java.lang.String.valueOf(String.java:2994) at java.lang.StringBuilder.append(StringBuilder.java:131) at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.processRow(AbstractJDBCTestElement.java:602) at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:558) at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:175) at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:85) at org.apache.jmeter.threads.JMeterThread.doSampling(JMeterThread.java:638) at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:558) at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:489) at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:256) at java.lang.Thread.run(Thread.java:748)

That should probably be fixed by the maintainers of the driver. (The API for DecimalFormat even states, that it is not thread safe, but that might have changed internally for the format method, as it is clearly synchronized now.)

You could add the formatting logic to your tests and see, whether your code falls into the same trap (it should).

To mitigate this on JMeters side, you could try to change the setting of "Handle ResultSet" from "Store as String" to "Store as Object". (But reading the source, it looks to me, that we always build the string, so it will probably not help)

If it doesn't help (which I fear, it will not), we should think about changing this part of the code in JMeter.

We have to think about:

  • should we use special cases for the JDBC data types to get the values and format them on our own?
  • should we skip formatting them, when the result set is not stored as a string?
  • more?

asfimport avatar May 05 '22 18:05 asfimport

@FSchumacher (migrated from Bugzilla): If you are willing to patch JMeter yourself, you could try the attached patch, which might help (for double/float formatting). I believe, that this code path should skip the string formatting in the JDBC driver and use a less synchronized code path.

I am unsure, whether we should follow this path, as up until now I haven't heard of other drivers having the same problem and there are a lot of types in SQL :)

Created attachment typed-objects.diff: Get typed objects when processing rows

typed-objects.diff
diff --git a/src/protocol/jdbc/src/main/java/org/apache/jmeter/protocol/jdbc/AbstractJDBCTestElement.java b/src/protocol/jdbc/src/main/java/org/apache/jmeter/protocol/jdbc/AbstractJDBCTestElement.java
index 2282216b1f..744a103a03 100644
--- a/src/protocol/jdbc/src/main/java/org/apache/jmeter/protocol/jdbc/AbstractJDBCTestElement.java
+++ b/src/protocol/jdbc/src/main/java/org/apache/jmeter/protocol/jdbc/AbstractJDBCTestElement.java
@@ -588,17 +588,14 @@ public abstract class AbstractJDBCTestElement extends AbstractTestElement implem
         Map<String, Object> row = null;
         currentIterationIndex++;
         for (int i = 1; i <= numColumns; i++) {
-            Object o = rs.getObject(i);
-            if(results != null) {
-                if(row == null) {
+            Object o = getTypedObject(rs, i);
+            if (results != null) {
+                if (row == null) {
                     row = new HashMap<>(numColumns);
                     results.add(row);
                 }
                 row.put(meta.getColumnLabel(i), o);
             }
-            if (o instanceof byte[]) {
-                o = new String((byte[]) o, ENCODING);
-            }
             sb.append(o);
             if (i==numColumns){
                 sb.append('\n');
@@ -607,7 +604,7 @@ public abstract class AbstractJDBCTestElement extends AbstractTestElement implem
             }
             if (i <= varNames.length) { // i starts at 1
                 String name = varNames[i - 1].trim();
-                if (name.length()>0){ // Save the value in the variable if present
+                if (!name.isEmpty()) { // Save the value in the variable if present
                     jmvars.put(name+UNDERSCORE+currentIterationIndex, o == null ? null : o.toString());
                 }
             }
@@ -615,6 +612,25 @@ public abstract class AbstractJDBCTestElement extends AbstractTestElement implem
         return currentIterationIndex;
     }
 
+    private Object getTypedObject(ResultSet rs, int i) throws SQLException {
+        int columnType = rs.getMetaData().getColumnType(i);
+        Object result;
+        switch (columnType) {
+            case Types.FLOAT:
+                result = rs.getFloat(i);
+                break;
+            case Types.DOUBLE:
+                result = rs.getDouble(i);
+                break;
+            default:
+                result = rs.getObject(i);
+        }
+        if (o instanceof byte[]) {
+            o = new String((byte[]) o, ENCODING);
+        }
+        return result;
+    }
+
     public static void close(Connection c) {
         try {
             if (c != null) {

asfimport avatar May 05 '22 18:05 asfimport

feng (migrated from Bugzilla): To Felix Schumacher I've been too busy lately to reply to you. Thanks for your advice.The maintainers of the driver have confirmed the parsing problems. It seems they use static parsing object for all threads resultset. Since they fix this,the test performance is better.But it still have a big difference from our own tests using my own program.

Then i read some code in ApacheJMeter_jdbc.jar,i found this in AbstractJDBCTestElement.class: if (resultSetMaxRows < 0) { while (rs.next()) { currentIterationIndex = processRow(rs, meta, sb, numColumns, jmvars, varNames, results, currentIterationIndex); } } else { while (currentIterationIndex < resultSetMaxRows && rs.next()) { currentIterationIndex = processRow(rs, meta, sb, numColumns, jmvars, varNames, results, currentIterationIndex); } } My understanding for these codes is : if i don't set the variable : resultSetMaxRows , jmeter will parse all datas in resultset. According to the manunal , i set the "Limit Resultset" to 10, which i can't be sure it's the parameter "resultSetMaxRows". But the results are good. The result met my requirement. I read the manunal , still i have some questions hope to be answered.

First: Is the variable "Limit Resultset" means "resultSetMaxRows " in the code?

Second question which is most concerned : For example, a query sql returns 1,000,000 rows. If i set the "Limit Resultset" to 10, will jmeter still got 1,000,000 rows from database server , but only show the first 10 rows. I want jmeter put pressure on database server , but don't want the parsing blocked the pressure. By the way , don't worry about the dolphindb jdbc driver, i have confirmed the driver won't limit the results , even if the total number of results is large.

Hope for your reply. Thanks !

asfimport avatar May 10 '22 12:05 asfimport

feng (migrated from Bugzilla):

Continue the above, is there any way to only count the number of results instead of parsing all the resultset data .

Sometimes , i just want to simplely verifyed the rows of the results . Make sure every query sql returns a correct result .

Now it seems, if i don't set the "Limit Resultset", jmeter will parse all data using while loop which i think takes a long time if the results are huge.

I think if there is an option to just count the numbers instead of parsing resultsets , that will be very helpful.

If there's some error in my understanding,please point them out.

By the way , I didn't receive the email for the last comment, that's strange.

asfimport avatar May 11 '22 02:05 asfimport

Antonio Gomes Rodrigues (migrated from Bugzilla): Hi, why don't you just do a select count?

asfimport avatar May 11 '22 07:05 asfimport

feng (migrated from Bugzilla): (In reply to Antonio Gomes Rodrigues from comment 9)

Hi, why don't you just do a select count?

Well, because it dosen't match my client's need. So , back to my previous question :

" Second question which is most concerned : For example, a query sql returns 1,000,000 rows. If i set the "Limit Resultset" to 10, will jmeter still got 1,000,000 rows from database server , but only show the first 10 rows. I want jmeter put pressure on database server , but don't want the parsing blocked the pressure. By the way , don't worry about the dolphindb jdbc driver, i have confirmed the driver won't limit the results , even if the total number of results is large.

" If limit resultset dosen't limit the query results, only limit the display result,we can accept this .

asfimport avatar May 11 '22 08:05 asfimport