Bug #57662 Incorrect Query Duration When useNanosForElapsedTime Enabled

• Submitted: 22 Oct 2010 15:01
• Modified: 5 Sep 2012 18:09
• Reporter: John McCarthy
• Status: Closed
• Category: Connector / J
• Severity: S3 (Non-critical)
• Version: 5.1.13
• OS: Any
• Assigned to: Alexander Soklakov
• CPU Architecture: Any

[22 Oct 2010 15:01] John McCarthy

Description:
With profileSQL=true and useNanosForElapsedTime=true specified in the connection URL, query and fetch duration are not reported correctly.  Here is some sample output (with the calling method removed),
Profiler Event: [QUERY] ... duration: -247690281687828 ns, connection-id: 28894, statement-id: 999, resultset-id: 0, message: SET autocommit=1
Profiler Event: [FETCH] ... duration: 247690281816850 ns, connection-id: 28894, statement-id: 999, resultset-id: 0

I was attempting to determine how costly even simple database hits like toggling autocommit are, and this seems like a perfect use case for useNanosForElapsedTime, as autocommit toggles were reported executed in zero milliseconds.

How to repeat:
1.  Set profileSQL=true and useNanosForElapsedTime=true in a JDBC connection url.  
2.  Enable a logger.  For example, add logger=com.mysql.jdbc.log.StandardLogger to the JDBC connection url.
3.  Establish a connection, and execute queries with this connection.  
4.  Examine query and fetch duration time in the log output.

Suggested fix:
The issue is in com.mysql.jdbc.MysqlIO.sqlQueryDirect().  The variable queryStartTime uses getCurrentTimeNanosOrMillis(), but queryEndTime is assigned System.currentTimeMillis() instead (line 2110 in version 5.1.13).  Not using getCurrentTimeNanosOrMillis() to assign queryEndTime causes both the query and fetch times to be incorrect.  

System.currentTimeMillis() also appears to be used a number of other times in MysqlIO.  Perhaps those calls could also be reviewed to see if getCurrentTimeNanosOrMillis() would be more appropriate.

[27 Jul 2011 22:23] Knut Forkalsrud

I can confirm this bug, it is somewhat annoying, and the fix as detailed above is obvious.
From what I can tell all the other uses of System.currentTimeMillis() in MysqlIO.java are correct.
The only other thing I would change is the cast to int near line 1426 of ServerPreparedStatement.java.  There is no point casting the duration to an int, it will only limit the durations that can reliably be reported (with useNanosForElapsedTime enabled) to 2^31 nanoseconds, or about 21.5 seconds.

[3 Jul 2012 11:36] Alexander Soklakov

Hi John,

Thank you for the bug report.

Verified as described.

[5 Sep 2012 18:09] John Russell

Added to changelog for 5.1.22: 

With profileSQL=true and useNanosForElapsedTime=true specified in the
connection URL, query and fetch duration were not reported correctly.
The com.mysql.jdbc.MysqlIO.sqlQueryDirect() method always measured
times in milliseconds rather than switching between milliseconds and
nanoseconds.