34: Feature : show the time taken to establish the connection

Author: sylvainlaurent

README.md

@@ -3,6 +3,7 @@
 ## Purpose
 Measuring performance of SQL statements executed through JDBC.
 
+(click on the image below for an overview of the features)
 [![Click here for an overview of the features](http://s159433608.onlinehome.fr/overview.png)](https://www.thinglink.com/scene/512018881544454146)
 
 
@@ -18,7 +19,7 @@ Although other tools already exist around JDBC performance monitoring ([log4jdbc
  - the connection between the monitored java application (JDBC proxy driver) and the console can be initiated from either side
 - Logging of bound values of prepared statements, including the name of the set* method called to bind the value (very helpful to distinguish setDate and setTimestamp to understand [why Oracle does not use an index](http://docs.oracle.com/cd/E16655_01/java.121/e17657/apxref.htm#JJDBC28919) )
 - Separate measure of statement execution time and result set iteration time
-- Measures commit/rollback times
+- Measures connection creation and commit/rollback durations
 - Handling of batched statements
 - Logging of SQLExceptions
 - Displays the `queryTimeout` of each statement (no value means 0 or no timeout) (since 0.5.0)
@@ -58,7 +59,8 @@ Although other tools already exist around JDBC performance monitoring ([log4jdbc
 The source code is available on GitHub : https://github.com/sylvainlaurent/JDBC-Performance-Logger
 
 ### How to build source
-Use Maven and a JDK 7, and run `mvn clean package` in the root directory of the git repository. The binary distribution is then available in `jdbc-perf-logger-gui`.
+Use Maven and a JDK >=7, and run `mvn clean package` in the root directory of the git repository. The binary distribution is then available in `jdbc-perf-logger-gui`. You need a JDK 8 to be able to run tests present in the module `jdbc-perf-logger-java8-tests`.
+
 ### How to create a release
 `mvn release:prepare release:perform` and answer the questions about version number.
 

jdbc-perf-logger-driver/src/main/java/ch/sla/jdbcperflogger/driver/WrappingDriver.java

@@ -66,7 +66,9 @@ public Connection connect(@Nullable final String url, @Nullable final Properties
         assert url != null;
         LOGGER.debug("connect url=[{}]", url);
         final String unWrappedUrl = extractUrlForWrappedDriver(url);
+        final long startNanos = System.nanoTime();
         Connection connection = DriverManager.getConnection(unWrappedUrl, info);
+        final long connectionCreationDuration = System.nanoTime() - startNanos;
 
         final Properties cleanedConnectionProperties = new Properties();
         if (info != null) {
@@ -82,7 +84,7 @@ public Connection connect(@Nullable final String url, @Nullable final Properties
         connection = (Connection) Proxy.newProxyInstance(WrappingDriver.class.getClassLoader(),
                 Utils.extractAllInterfaces(connection.getClass()), connectionInvocationHandler);
 
-        PerfLoggerRemoting.connectionCreated(connectionInvocationHandler);
+        PerfLoggerRemoting.connectionCreated(connectionInvocationHandler, connectionCreationDuration);
 
         return connection;
     }

jdbc-perf-logger-driver/src/main/java/ch/sla/jdbcperflogger/logger/PerfLoggerRemoting.java

@@ -133,10 +133,11 @@ static InputStream openConfigFile(final String location) {
     private PerfLoggerRemoting() {
     }
 
-    public static void connectionCreated(final LoggingConnectionInvocationHandler connectionHandler) {
+    public static void connectionCreated(final LoggingConnectionInvocationHandler connectionHandler,
+            final long connectionCreationDuration) {
         final ConnectionInfo info = new ConnectionInfo(connectionHandler.getConnectionUuid(),
                 connectionHandler.getConnectionId(), connectionHandler.getUrl(), new Date(),
-                connectionHandler.getConnectionProperties());
+                connectionCreationDuration, connectionHandler.getConnectionProperties());
         synchronized (connectionToInfo) {
             connectionToInfo.put(connectionHandler, info);
             postLog(info);

jdbc-perf-logger-driver/src/main/java/ch/sla/jdbcperflogger/model/ConnectionInfo.java

@@ -11,17 +11,19 @@ public class ConnectionInfo implements LogMessage {
     private final int connectionNumber;
     private final String url;
     private final Date creationDate;
+    private final long connectionCreationDuration;
     /**
      * Connection props without password
      */
     private final Properties connectionProperties;
 
     public ConnectionInfo(final UUID uuid, final int connectionNumber, final String url, final Date creationDate,
-            final Properties connectionProperties) {
+            final long connectionCreationDuration, final Properties connectionProperties) {
         this.uuid = uuid;
         this.connectionNumber = connectionNumber;
         this.url = url;
         this.creationDate = creationDate;
+        this.connectionCreationDuration = connectionCreationDuration;
         this.connectionProperties = connectionProperties;
     }
 
@@ -45,13 +47,18 @@ public Properties getConnectionProperties() {
         return connectionProperties;
     }
 
+    public long getConnectionCreationDuration() {
+        return connectionCreationDuration;
+    }
+
     @Override
     public String toString() {
         return "ConnectionInfo["//
                 + "connectionId=" + uuid//
                 + ", connectionNumber=" + connectionNumber//
                 + ", url=" + url//
                 + ", creationDate=" + creationDate//
+                + ", connectionCreationDuration=" + connectionCreationDuration//
                 + "]";
     }
 }

jdbc-perf-logger-gui/src/main/java/ch/sla/jdbcperflogger/console/db/LogRepositoryReadJdbc.java

@@ -207,7 +207,7 @@ public DetailedViewStatementLog getStatementLog(final long id) {
                 + "statement_log.threadName, statement_log.exception, "//
                 + "statement_log.connectionId,"//
                 + "connection_info.connectionNumber, connection_info.url, connection_info.creationDate,"//
-                + "connection_info.connectionProperties "//
+                + "connection_info.connectionCreationDurationNanos, connection_info.connectionProperties "//
                 + "from statement_log join connection_info on (statement_log.connectionId=connection_info.connectionId) "//
                 + "where statement_log.id=?";
 
@@ -231,10 +231,11 @@ public DetailedViewStatementLog getStatementLog(final long id) {
                     final int connectionNumber = resultSet.getInt(i++);
                     final String connectionUrl = resultSet.getString(i++);
                     final Timestamp creationDate = resultSet.getTimestamp(i++);
+                    final long connectionCreationDurationNanos = resultSet.getLong(i++);
                     final Properties connectionProperties = (Properties) resultSet.getObject(i++);
 
                     final ConnectionInfo connectionInfo = new ConnectionInfo(connectionId, connectionNumber,
-                            connectionUrl, creationDate, connectionProperties);
+                            connectionUrl, creationDate, connectionCreationDurationNanos, connectionProperties);
 
                     result = new DetailedViewStatementLog(logId, connectionInfo, tstamp.getTime(), statementType,
                             rawSql, filledSql, threadName, exception);

jdbc-perf-logger-gui/src/main/java/ch/sla/jdbcperflogger/console/db/LogRepositoryUpdateJdbc.java

@@ -319,13 +319,15 @@ public synchronized void addBatchedNonPreparedStatementsLog(final BatchedNonPrep
     public synchronized void addConnection(final ConnectionInfo connectionInfo) {
         LOGGER.debug("addConnection:{}", connectionInfo);
         try (PreparedStatement stmt = connectionUpdate
-                .prepareStatement("merge into connection_info (connectionId, connectionNumber, url, creationDate, connectionProperties)"//
-                        + " key(connectionId) values (?,?,?,?,?)")) {
+                .prepareStatement("merge into connection_info (connectionId, connectionNumber, url, creationDate, "//
+                        + "connectionCreationDurationNanos, connectionProperties)"//
+                        + " key(connectionId) values (?,?,?,?,?,?)")) {
             int i = 1;
             stmt.setObject(i++, connectionInfo.getUuid());
             stmt.setInt(i++, connectionInfo.getConnectionNumber());
             stmt.setString(i++, connectionInfo.getUrl());
             stmt.setTimestamp(i++, new Timestamp(connectionInfo.getCreationDate().getTime()));
+            stmt.setLong(i++, connectionInfo.getConnectionCreationDuration());
             stmt.setObject(i++, connectionInfo.getConnectionProperties());
 
             stmt.execute();

jdbc-perf-logger-gui/src/main/java/ch/sla/jdbcperflogger/console/ui/PerfLoggerController.java

@@ -42,6 +42,7 @@
 import ch.sla.jdbcperflogger.console.db.LogSearchCriteria;
 import ch.sla.jdbcperflogger.console.db.ResultSetAnalyzer;
 import ch.sla.jdbcperflogger.console.net.AbstractLogReceiver;
+import ch.sla.jdbcperflogger.model.ConnectionInfo;
 
 public class PerfLoggerController {
     private final static Logger LOGGER = LoggerFactory.getLogger(PerfLoggerController.class);
@@ -260,6 +261,7 @@ private void statementSelected(@Nullable final Long logId) {
         String txt2 = "";
         String connectionUrl = null;
         String connectionCreationDate = null;
+        Long connectionCreationDurationMillis = null;
         String connectionPropertiesString = null;
         DetailedViewStatementLog statementLog = null;
         if (logId != null) {
@@ -290,10 +292,13 @@ private void statementSelected(@Nullable final Long logId) {
                 }
                 deltaTimestampBaseMillis = statementLog.getTimestamp();
 
-                connectionUrl = statementLog.getConnectionInfo().getUrl();
-                connectionPropertiesString = statementLog.getConnectionInfo().getConnectionProperties().toString();
+                final ConnectionInfo connectionInfo = statementLog.getConnectionInfo();
+                connectionUrl = connectionInfo.getUrl();
+                connectionPropertiesString = connectionInfo.getConnectionProperties().toString();
                 final SimpleDateFormat format = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
-                connectionCreationDate = format.format(statementLog.getConnectionInfo().getCreationDate());
+                connectionCreationDate = format.format(connectionInfo.getCreationDate());
+                connectionCreationDurationMillis = TimeUnit.NANOSECONDS.toMillis(connectionInfo
+                        .getConnectionCreationDuration());
                 break;
             case RAW_SQL:
                 if (statementLog.getStatementType() != null) {
@@ -345,6 +350,8 @@ private void statementSelected(@Nullable final Long logId) {
         perfLoggerPanel.txtFieldFilledSql.select(0, 0);
         perfLoggerPanel.connectionUrlField.setText(connectionUrl);
         perfLoggerPanel.connectionCreationDateField.setText(connectionCreationDate);
+        perfLoggerPanel.connectionCreationDurationField
+                .setText(connectionCreationDurationMillis != null ? connectionCreationDurationMillis.toString() : "");
         perfLoggerPanel.connectionPropertiesField.setText(connectionPropertiesString);
 
         perfLoggerPanel.setDeltaTimestampBaseMillis(deltaTimestampBaseMillis);

jdbc-perf-logger-gui/src/main/java/ch/sla/jdbcperflogger/console/ui/PerfLoggerPanel.java

@@ -122,6 +122,7 @@ public class PerfLoggerPanel extends JPanel {
     JTextField connectionCreationDateField;
     private JTextField sqlClauseField;
     JTextField connectionPropertiesField;
+    JTextField connectionCreationDurationField;
 
     public PerfLoggerPanel(final PerfLoggerController perfLoggerController) {
 
@@ -545,7 +546,7 @@ public void actionPerformed(@Nullable final ActionEvent e) {
         final GridBagLayout gbl_panelConnectionInfo = new GridBagLayout();
         gbl_panelConnectionInfo.columnWidths = new int[] { 0, 0, 0, 0, 0 };
         gbl_panelConnectionInfo.rowHeights = new int[] { 0, 0, 0, 0 };
-        gbl_panelConnectionInfo.columnWeights = new double[] { 0.0, 1.0, 0.0, 0.0, Double.MIN_VALUE };
+        gbl_panelConnectionInfo.columnWeights = new double[] { 0.0, 0.0, 0.0, 1.0, Double.MIN_VALUE };
         gbl_panelConnectionInfo.rowWeights = new double[] { 0.0, 0.0, 0.0, Double.MIN_VALUE };
         panelConnectionInfo.setLayout(gbl_panelConnectionInfo);
 
@@ -559,8 +560,9 @@ public void actionPerformed(@Nullable final ActionEvent e) {
 
         connectionUrlField = new JTextField();
         final GridBagConstraints gbc_connectionUrlField = new GridBagConstraints();
+        gbc_connectionUrlField.gridwidth = 3;
         gbc_connectionUrlField.fill = GridBagConstraints.HORIZONTAL;
-        gbc_connectionUrlField.insets = new Insets(0, 0, 5, 5);
+        gbc_connectionUrlField.insets = new Insets(0, 0, 5, 0);
         gbc_connectionUrlField.gridx = 1;
         gbc_connectionUrlField.gridy = 0;
         panelConnectionInfo.add(connectionUrlField, gbc_connectionUrlField);
@@ -570,35 +572,51 @@ public void actionPerformed(@Nullable final ActionEvent e) {
         final GridBagConstraints gbc_lblCreated = new GridBagConstraints();
         gbc_lblCreated.anchor = GridBagConstraints.EAST;
         gbc_lblCreated.insets = new Insets(0, 0, 5, 5);
-        gbc_lblCreated.gridx = 2;
-        gbc_lblCreated.gridy = 0;
+        gbc_lblCreated.gridx = 0;
+        gbc_lblCreated.gridy = 1;
         panelConnectionInfo.add(lblCreated, gbc_lblCreated);
 
         connectionCreationDateField = new JTextField();
         final GridBagConstraints gbc_connectionCreationDateField = new GridBagConstraints();
         gbc_connectionCreationDateField.fill = GridBagConstraints.HORIZONTAL;
-        gbc_connectionCreationDateField.insets = new Insets(0, 0, 5, 0);
-        gbc_connectionCreationDateField.gridx = 3;
-        gbc_connectionCreationDateField.gridy = 0;
+        gbc_connectionCreationDateField.insets = new Insets(0, 0, 5, 5);
+        gbc_connectionCreationDateField.gridx = 1;
+        gbc_connectionCreationDateField.gridy = 1;
         panelConnectionInfo.add(connectionCreationDateField, gbc_connectionCreationDateField);
         connectionCreationDateField.setColumns(15);
 
+        final JLabel lblCreationDuration = new JLabel("Creation duration (ms):");
+        final GridBagConstraints gbc_lblCreationDuration = new GridBagConstraints();
+        gbc_lblCreationDuration.anchor = GridBagConstraints.EAST;
+        gbc_lblCreationDuration.insets = new Insets(0, 0, 5, 5);
+        gbc_lblCreationDuration.gridx = 2;
+        gbc_lblCreationDuration.gridy = 1;
+        panelConnectionInfo.add(lblCreationDuration, gbc_lblCreationDuration);
+
+        connectionCreationDurationField = new JTextField();
+        final GridBagConstraints gbc_creationDurationField = new GridBagConstraints();
+        gbc_creationDurationField.insets = new Insets(0, 0, 5, 0);
+        gbc_creationDurationField.fill = GridBagConstraints.HORIZONTAL;
+        gbc_creationDurationField.gridx = 3;
+        gbc_creationDurationField.gridy = 1;
+        panelConnectionInfo.add(connectionCreationDurationField, gbc_creationDurationField);
+        connectionCreationDurationField.setColumns(10);
+
         final JLabel lblConectionProperties = new JLabel("Properties:");
         final GridBagConstraints gbc_lblConectionProperties = new GridBagConstraints();
         gbc_lblConectionProperties.anchor = GridBagConstraints.EAST;
-        gbc_lblConectionProperties.insets = new Insets(0, 0, 5, 5);
+        gbc_lblConectionProperties.insets = new Insets(0, 0, 0, 5);
         gbc_lblConectionProperties.gridx = 0;
-        gbc_lblConectionProperties.gridy = 1;
+        gbc_lblConectionProperties.gridy = 2;
         panelConnectionInfo.add(lblConectionProperties, gbc_lblConectionProperties);
         lblConectionProperties.setToolTipText("(Password property removed)");
 
         connectionPropertiesField = new JTextField();
         final GridBagConstraints gbc_connectionPropertiesField = new GridBagConstraints();
-        gbc_connectionPropertiesField.insets = new Insets(0, 0, 5, 0);
         gbc_connectionPropertiesField.fill = GridBagConstraints.HORIZONTAL;
         gbc_connectionPropertiesField.gridwidth = 3;
         gbc_connectionPropertiesField.gridx = 1;
-        gbc_connectionPropertiesField.gridy = 1;
+        gbc_connectionPropertiesField.gridy = 2;
         panelConnectionInfo.add(connectionPropertiesField, gbc_connectionPropertiesField);
         connectionPropertiesField.setColumns(10);
 

jdbc-perf-logger-gui/src/main/resources/initdb.sql

@@ -7,7 +7,7 @@ SET UNDO_LOG 0;
 
 create table if not exists connection_info 
     (id identity, connectionId UUID not null, connectionNumber int not null, 
-    url varchar not null, creationDate timestamp not null, connectionProperties other);
+    url varchar not null, creationDate timestamp not null, connectionCreationDurationNanos bigInt, connectionProperties other);
 
 create table if not exists statement_log 
     (id identity, connectionId UUID not null, logId UUID not null, tstamp timestamp not null, statementType tinyInt not null, 

jdbc-perf-logger-gui/src/test/java/ch/sla/jdbcperflogger/console/db/AbstractLogRepositoryTest.java

@@ -33,18 +33,28 @@ public void tearDown() {
         repositoryRead.dispose();
     }
 
-    protected StatementLog insert1Log() {
+    protected ConnectionInfo insert1Connection() {
         final Properties connProps = new Properties();
         connProps.setProperty("myprop", "myval");
-        final ConnectionInfo connectionInfo = new ConnectionInfo(randomUUID(), 12, "jdbc:toto", new Date(), connProps);
+        final ConnectionInfo connectionInfo = new ConnectionInfo(randomUUID(), 12, "jdbc:toto", new Date(), 12,
+                connProps);
         repositoryUpdate.addConnection(connectionInfo);
+        return connectionInfo;
+    }
+
+    protected StatementLog insert1Log(final ConnectionInfo connectionInfo) {
 
         final StatementLog log = new StatementLog(connectionInfo.getUuid(), randomUUID(), System.currentTimeMillis(),
                 StatementType.BASE_NON_PREPARED_STMT, "myrawsql", Thread.currentThread().getName(), 123, true);
         repositoryUpdate.addStatementLog(log);
         return log;
     }
 
+    protected StatementLog insert1Log() {
+        final ConnectionInfo connectionInfo = insert1Connection();
+        return insert1Log(connectionInfo);
+    }
+
     protected int countRowsInTable(final String table) {
         try (Statement stmt = repositoryUpdate.connectionUpdate.createStatement()) {
             try (ResultSet rset = stmt.executeQuery("select count(1) from " + table)) {