From 28845b20ad8af7234cc2f54e0e9b620e495db07d Mon Sep 17 00:00:00 2001 From: msillanpaa Date: Wed, 13 Nov 2019 17:44:50 +0200 Subject: [PATCH 1/2] Add option profileQueries to allow timing all queries. --- src/main/core-api/java/com/mysql/cj/Query.java | 10 ++++++++++ .../com/mysql/cj/conf/PropertyDefinitions.java | 3 +++ .../java/com/mysql/cj/conf/PropertyKey.java | 1 + .../java/com/mysql/cj/AbstractQuery.java | 13 +++++++++++++ .../java/com/mysql/cj/ServerPreparedQuery.java | 16 +++++++++++++--- .../com/mysql/cj/protocol/a/NativeProtocol.java | 16 +++++++++++++--- .../mysql/cj/LocalizedErrorMessages.properties | 1 + .../java/com/mysql/cj/jdbc/StatementImpl.java | 12 ++++++++++++ 8 files changed, 66 insertions(+), 6 deletions(-) diff --git a/src/main/core-api/java/com/mysql/cj/Query.java b/src/main/core-api/java/com/mysql/cj/Query.java index c142f2b4..7214ac97 100644 --- a/src/main/core-api/java/com/mysql/cj/Query.java +++ b/src/main/core-api/java/com/mysql/cj/Query.java @@ -89,6 +89,16 @@ void setTimeoutInMillis(int timeoutInMillis); + void setElapsedTime(long elapsedTime); + + /** + * Returns the elapsed time for the server to process the query. + * profileQueries must be enabled or -1 will be returned. + * + * @return the elapsed time or -1. + */ + long getElapsedTime(); + CancelQueryTask startQueryTimer(Query stmtToCancel, int timeout); AtomicBoolean getStatementExecuting(); diff --git a/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java b/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java index 901eabe1..7e11688c 100644 --- a/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java +++ b/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java @@ -726,6 +726,9 @@ new BooleanPropertyDefinition(PropertyKey.autoGenerateTestcaseScript, DEFAULT_VALUE_FALSE, RUNTIME_MODIFIABLE, Messages.getString("ConnectionProperties.autoGenerateTestcaseScript"), "3.1.9", CATEGORY_DEBUGING_PROFILING, 18), + new BooleanPropertyDefinition(PropertyKey.profileQueries, DEFAULT_VALUE_FALSE, RUNTIME_MODIFIABLE, + Messages.getString("ConnectionProperties.profileQueries"), "8.0.18", CATEGORY_DEBUGING_PROFILING, 19), + // // CATEGORY_EXCEPTIONS // diff --git a/src/main/core-api/java/com/mysql/cj/conf/PropertyKey.java b/src/main/core-api/java/com/mysql/cj/conf/PropertyKey.java index 8a9936b0..49788dc6 100644 --- a/src/main/core-api/java/com/mysql/cj/conf/PropertyKey.java +++ b/src/main/core-api/java/com/mysql/cj/conf/PropertyKey.java @@ -172,6 +172,7 @@ processEscapeCodesForPrepStmts("processEscapeCodesForPrepStmts", true), // profilerEventHandler("profilerEventHandler", true), // profileSQL("profileSQL", true), // + profileQueries("profileQueries", true), // propertiesTransform("propertiesTransform", true), // queriesBeforeRetryMaster("queriesBeforeRetryMaster", true), // queryInterceptors("queryInterceptors", true), // diff --git a/src/main/core-impl/java/com/mysql/cj/AbstractQuery.java b/src/main/core-impl/java/com/mysql/cj/AbstractQuery.java index a42e29d4..637cbfa7 100644 --- a/src/main/core-impl/java/com/mysql/cj/AbstractQuery.java +++ b/src/main/core-impl/java/com/mysql/cj/AbstractQuery.java @@ -87,6 +87,9 @@ /** Has clearWarnings() been called? */ protected boolean clearWarningsCalled = false; + /** Elapsed time of the execution */ + private long elapsedTime = -1; + public AbstractQuery(NativeSession sess) { statementCounter++; this.session = sess; @@ -104,6 +107,16 @@ public void setCancelStatus(CancelStatus cs) { this.cancelStatus = cs; } + @Override + public long getElapsedTime() { + return elapsedTime; + } + + @Override + public void setElapsedTime(long elapsedTime) { + this.elapsedTime = elapsedTime; + } + @Override public void checkCancelTimeout() { synchronized (this.cancelTimeoutMutex) { diff --git a/src/main/core-impl/java/com/mysql/cj/ServerPreparedQuery.java b/src/main/core-impl/java/com/mysql/cj/ServerPreparedQuery.java index d813e714..8dd18664 100644 --- a/src/main/core-impl/java/com/mysql/cj/ServerPreparedQuery.java +++ b/src/main/core-impl/java/com/mysql/cj/ServerPreparedQuery.java @@ -74,6 +74,9 @@ /** The "profileSQL" connection property value */ protected boolean profileSQL = false; + /** The "profileQueries" connection property value */ + private boolean profileQueries = false; + /** The "gatherPerfMetrics" connection property value */ protected boolean gatherPerfMetrics; @@ -101,6 +104,7 @@ public static ServerPreparedQuery getInstance(NativeSession sess) { protected ServerPreparedQuery(NativeSession sess) { super(sess); this.profileSQL = sess.getPropertySet().getBooleanProperty(PropertyKey.profileSQL).getValue(); + this.profileQueries = sess.getPropertySet().getBooleanProperty(PropertyKey.profileQueries).getValue(); this.gatherPerfMetrics = sess.getPropertySet().getBooleanProperty(PropertyKey.gatherPerfMetrics).getValue(); this.logSlowQueries = sess.getPropertySet().getBooleanProperty(PropertyKey.logSlowQueries).getValue(); this.useAutoSlowLog = sess.getPropertySet().getBooleanProperty(PropertyKey.autoSlowLog).getValue(); @@ -318,9 +322,9 @@ public NativePacketPayload prepareExecutePacket() { public NativePacketPayload sendExecutePacket(NativePacketPayload packet, String queryAsString) { // TODO queryAsString should be shared instead of passed - boolean countDuration = this.profileSQL || this.logSlowQueries || this.gatherPerfMetrics; + final boolean countDuration = this.profileSQL || this.profileQueries || this.logSlowQueries || this.gatherPerfMetrics; - long begin = countDuration ? this.session.getCurrentTimeNanosOrMillis() : 0; + final long begin = countDuration ? this.session.getCurrentTimeNanosOrMillis() : 0; resetCancelledState(); @@ -342,7 +346,13 @@ public NativePacketPayload sendExecutePacket(NativePacketPayload packet, String timeoutTask = null; } - long elapsedTime = countDuration ? queryEndTime - begin : 0L; + final long elapsedTime; + if (countDuration) { + elapsedTime = queryEndTime - begin; + setElapsedTime(elapsedTime); + } else { + elapsedTime = 0L; + } if (this.logSlowQueries) { this.queryWasSlow = this.useAutoSlowLog ? // diff --git a/src/main/protocol-impl/java/com/mysql/cj/protocol/a/NativeProtocol.java b/src/main/protocol-impl/java/com/mysql/cj/protocol/a/NativeProtocol.java index 3c28d45f..b9611535 100644 --- a/src/main/protocol-impl/java/com/mysql/cj/protocol/a/NativeProtocol.java +++ b/src/main/protocol-impl/java/com/mysql/cj/protocol/a/NativeProtocol.java @@ -167,6 +167,7 @@ private boolean useAutoSlowLog; private boolean profileSQL = false; + private boolean profileQueries = false; private long slowQueryThreshold; @@ -250,6 +251,7 @@ public void init(Session sess, SocketConnection phConnection, PropertySet propSe this.logSlowQueries = this.propertySet.getBooleanProperty(PropertyKey.logSlowQueries).getValue(); this.maxAllowedPacket = this.propertySet.getIntegerProperty(PropertyKey.maxAllowedPacket); this.profileSQL = this.propertySet.getBooleanProperty(PropertyKey.profileSQL).getValue(); + this.profileQueries = this.propertySet.getBooleanProperty(PropertyKey.profileQueries).getValue(); this.autoGenerateTestcaseScript = this.propertySet.getBooleanProperty(PropertyKey.autoGenerateTestcaseScript).getValue(); this.useServerPrepStmts = this.propertySet.getBooleanProperty(PropertyKey.useServerPrepStmts); @@ -911,7 +913,9 @@ public void reclaimLargeReusablePacket() { public final T sendQueryPacket(Query callingQuery, NativePacketPayload queryPacket, int maxRows, boolean streamResults, ColumnDefinition cachedMetadata, ProtocolEntityFactory resultSetFactory) throws IOException { - long queryStartTime = this.profileSQL || this.logSlowQueries ? getCurrentTimeNanosOrMillis() : 0; + final boolean countDuration = this.profileSQL || this.profileQueries || this.logSlowQueries; + + final long queryStartTime = countDuration ? getCurrentTimeNanosOrMillis() : 0; this.statementExecutionDepth++; @@ -940,8 +944,14 @@ public void reclaimLargeReusablePacket() { // Send query command and sql query string NativePacketPayload resultPacket = sendCommand(queryPacket, false, 0); - long queryEndTime = this.profileSQL || this.logSlowQueries ? getCurrentTimeNanosOrMillis() : 0L; - long queryDuration = this.profileSQL || this.logSlowQueries ? queryEndTime - queryStartTime : 0L; + final long queryEndTime = countDuration ? getCurrentTimeNanosOrMillis() : 0L; + final long queryDuration; + if (countDuration && callingQuery != null) { + queryDuration = queryEndTime - queryStartTime; + callingQuery.setElapsedTime(queryDuration); + } else { + queryDuration = 0L; + } boolean queryWasSlow = this.logSlowQueries && (this.useAutoSlowLog ? this.metricsHolder.checkAbonormallyLongQuery(queryDuration) : queryDuration > this.propertySet.getIntegerProperty(PropertyKey.slowQueryThresholdMillis).getValue()); diff --git a/src/main/resources/com/mysql/cj/LocalizedErrorMessages.properties b/src/main/resources/com/mysql/cj/LocalizedErrorMessages.properties index e981ed0d..1abe2352 100644 --- a/src/main/resources/com/mysql/cj/LocalizedErrorMessages.properties +++ b/src/main/resources/com/mysql/cj/LocalizedErrorMessages.properties @@ -804,6 +804,7 @@ ConnectionProperties.prepStmtCacheSqlLimit=If prepared statement caching is enab ConnectionProperties.processEscapeCodesForPrepStmts=Should the driver process escape codes in queries that are prepared? Default escape processing behavior in non-prepared statements must be defined with the property 'enableEscapeProcessing'. ConnectionProperties.profilerEventHandler=Name of a class that implements the interface com.mysql.cj.log.ProfilerEventHandler that will be used to handle profiling/tracing events. ConnectionProperties.profileSQL=Trace queries and their execution/fetch times to the configured 'profilerEventHandler' +ConnectionProperties.profileQueries=Enables support for 'Query.getElapsedTime() ' in postProcess to all configured QueryInterceptors. ConnectionProperties.connectionPropertiesTransform=An implementation of com.mysql.cj.conf.ConnectionPropertiesTransform that the driver will use to modify URL properties passed to the driver before attempting a connection ConnectionProperties.queriesBeforeRetryMaster=Number of queries to issue before falling back to the primary host when failed over (when using multi-host failover). Whichever condition is met first, 'queriesBeforeRetryMaster' or 'secondsBeforeRetryMaster' will cause an attempt to be made to reconnect to the primary host. Setting both properties to 0 disables the automatic fall back to the primary host at transaction boundaries. Defaults to 50. ConnectionProperties.reconnectAtTxEnd=If autoReconnect is set to true, should the driver attempt reconnections at the end of every transaction? diff --git a/src/main/user-impl/java/com/mysql/cj/jdbc/StatementImpl.java b/src/main/user-impl/java/com/mysql/cj/jdbc/StatementImpl.java index a836c237..d5e7f2dd 100644 --- a/src/main/user-impl/java/com/mysql/cj/jdbc/StatementImpl.java +++ b/src/main/user-impl/java/com/mysql/cj/jdbc/StatementImpl.java @@ -2237,6 +2237,18 @@ public void setTimeoutInMillis(int timeoutInMillis) { this.query.setTimeoutInMillis(timeoutInMillis); } + @Override + public long getElapsedTime() { + return this.query.getElapsedTime(); + } + + @Override + public void setElapsedTime(long elapsedTime) { + if (this.query != null) { + this.query.setElapsedTime(elapsedTime); + } + } + @Override public AtomicBoolean getStatementExecuting() { return this.query.getStatementExecuting(); From 5b1848785ffe67b0edeb42421cb88367caece36a Mon Sep 17 00:00:00 2001 From: msillanpaa Date: Wed, 20 Nov 2019 16:37:45 +0200 Subject: [PATCH 2/2] Bump up to appropriate patch version 8.0.19 for property ConnectionProperties.profileQueries. --- .../core-api/java/com/mysql/cj/conf/PropertyDefinitions.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java b/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java index 7e11688c..69a007ee 100644 --- a/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java +++ b/src/main/core-api/java/com/mysql/cj/conf/PropertyDefinitions.java @@ -727,7 +727,7 @@ Messages.getString("ConnectionProperties.autoGenerateTestcaseScript"), "3.1.9", CATEGORY_DEBUGING_PROFILING, 18), new BooleanPropertyDefinition(PropertyKey.profileQueries, DEFAULT_VALUE_FALSE, RUNTIME_MODIFIABLE, - Messages.getString("ConnectionProperties.profileQueries"), "8.0.18", CATEGORY_DEBUGING_PROFILING, 19), + Messages.getString("ConnectionProperties.profileQueries"), "8.0.19", CATEGORY_DEBUGING_PROFILING, 19), // // CATEGORY_EXCEPTIONS