From 573d1c028e6a19f8cbb710fb336b08e9869b384b Mon Sep 17 00:00:00 2001 From: Tiago Silva Date: Tue, 29 Aug 2023 13:07:37 +0100 Subject: [PATCH] Add some logs while Postgres queries are being executed This commit adds some extra logs to be shown while Postgres queries are being executed. The goal is to easily identify cases where a query is not being executed because it's waiting for the Database table to be unlocked first (due to another query being already executed for example). Since it's not easy to identify a query timeout that will work for all cases of queries that can be executed with PDB, at least being able to see in the logs that PDB is still executing a query helps to identify such scenarios. --- .../engine/impl/PostgreSqlEngine.java | 151 ++++++++---------- 1 file changed, 68 insertions(+), 83 deletions(-) diff --git a/src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java b/src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java index e74f4bd7..dbfc841e 100644 --- a/src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java +++ b/src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java @@ -37,7 +37,14 @@ import com.feedzai.commons.sql.abstraction.engine.impl.postgresql.PostgresSqlQueryExceptionHandler; import com.feedzai.commons.sql.abstraction.util.StringUtils; +import java.time.Duration; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; + import org.postgresql.Driver; import org.postgresql.PGProperty; import org.postgresql.util.PGobject; @@ -113,6 +120,13 @@ public class PostgreSqlEngine extends AbstractDatabaseEngine { */ public static final QueryExceptionHandler PG_QUERY_EXCEPTION_HANDLER = new PostgresSqlQueryExceptionHandler(); + /** + * The {@link ExecutorService} which will print some logs while Postgres {@link Statement update queries} are + * being executed. This will print a log from time to time in order to easily identify cases where the query might + * be stuck due to the database being locked because of another external query. + */ + private final ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor(); + /** * Creates a new PostgreSql connection. * @@ -236,10 +250,8 @@ protected void createTable(final DbEntity entity) throws DatabaseEngineException logger.trace(createTableStatement); - Statement s = null; try { - s = conn.createStatement(); - s.executeUpdate(createTableStatement); + executeUpdateQuery(createTableStatement); } catch (final SQLException ex) { if (ex.getSQLState().startsWith(NAME_ALREADY_EXISTS)) { logger.debug(dev, "'{}' is already defined", entity.getName()); @@ -247,14 +259,6 @@ protected void createTable(final DbEntity entity) throws DatabaseEngineException } else { throw new DatabaseEngineException("Something went wrong handling statement", ex); } - } finally { - try { - if (s != null) { - s.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } @@ -283,10 +287,8 @@ protected void addPrimaryKey(final DbEntity entity) throws DatabaseEngineExcepti logger.trace(addPrimaryKey); - Statement s = null; try { - s = conn.createStatement(); - s.executeUpdate(addPrimaryKey); + executeUpdateQuery(addPrimaryKey); } catch (final SQLException ex) { if (ex.getSQLState().startsWith(TABLE_CAN_ONLY_HAVE_ONE_PRIMARY_KEY)) { logger.debug(dev, "'{}' already has a primary key", entity.getName()); @@ -294,14 +296,6 @@ protected void addPrimaryKey(final DbEntity entity) throws DatabaseEngineExcepti } else { throw new DatabaseEngineException("Something went wrong handling statement", ex); } - } finally { - try { - if (s != null) { - s.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } @@ -334,10 +328,8 @@ protected void addIndexes(final DbEntity entity) throws DatabaseEngineException logger.trace(statement); - Statement s = null; try { - s = conn.createStatement(); - s.executeUpdate(statement); + executeUpdateQuery(statement); } catch (final SQLException ex) { if (ex.getSQLState().startsWith(NAME_ALREADY_EXISTS)) { logger.debug(dev, "'{}' is already defined", idxName); @@ -345,14 +337,6 @@ protected void addIndexes(final DbEntity entity) throws DatabaseEngineException } else { throw new DatabaseEngineException("Something went wrong handling statement", ex); } - } finally { - try { - if (s != null) { - s.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } } @@ -495,12 +479,10 @@ protected void dropSequences(DbEntity entity) throws DatabaseEngineException { @Override protected void dropTable(DbEntity entity) throws DatabaseEngineException { - Statement drop = null; + final String query = format("DROP TABLE %s CASCADE", quotize(entity.getName())); + logger.trace(query); try { - drop = conn.createStatement(); - final String query = format("DROP TABLE %s CASCADE", quotize(entity.getName())); - logger.trace(query); - drop.executeUpdate(query); + executeUpdateQuery(query); } catch (final SQLException ex) { if (ex.getSQLState().startsWith(TABLE_OR_VIEW_DOES_NOT_EXIST)) { logger.debug(dev, "Table '{}' does not exist", entity.getName()); @@ -508,21 +490,11 @@ protected void dropTable(DbEntity entity) throws DatabaseEngineException { } else { throw new DatabaseEngineException("Error dropping table", ex); } - } finally { - try { - if (drop != null) { - drop.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } @Override protected void dropColumn(DbEntity entity, String... columns) throws DatabaseEngineException { - Statement drop = null; - List removeColumns = new ArrayList<>(); removeColumns.add("ALTER TABLE"); removeColumns.add(quotize(entity.getName())); @@ -531,26 +503,17 @@ protected void dropColumn(DbEntity entity, String... columns) throws DatabaseEng cols.add("DROP COLUMN " + quotize(col)); } removeColumns.add(join(cols, ",")); + final String query = join(removeColumns, " "); + logger.trace(query); try { - drop = conn.createStatement(); - final String query = join(removeColumns, " "); - logger.trace(query); - drop.executeUpdate(query); + executeUpdateQuery(query); } catch (final SQLException ex) { if (ex.getMessage().startsWith(TABLE_OR_VIEW_DOES_NOT_EXIST)) { logger.debug(dev, "Table '{}' does not exist", entity.getName()); } else { throw new DatabaseEngineException("Error dropping column", ex); } - } finally { - try { - if (drop != null) { - drop.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } @@ -582,20 +545,10 @@ protected void addColumn(DbEntity entity, DbColumn... columns) throws DatabaseEn final String addColumnsStatement = join(addColumns, " "); logger.trace(addColumnsStatement); - Statement s = null; try { - s = conn.createStatement(); - s.executeUpdate(addColumnsStatement); + executeUpdateQuery(addColumnsStatement); } catch (final SQLException ex) { throw new DatabaseEngineException("Something went wrong handling statement", ex); - } finally { - try { - if (s != null) { - s.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } @@ -678,11 +631,9 @@ protected void addFks(final DbEntity entity, Set fks) throws DatabaseEngin quotizedForeignColumnsString ); - Statement alterTableStmt = null; + logger.trace(alterTable); try { - alterTableStmt = conn.createStatement(); - logger.trace(alterTable); - alterTableStmt.executeUpdate(alterTable); + executeUpdateQuery(alterTable); } catch (final SQLException ex) { if (ex.getSQLState().equals(CONSTRAINT_NAME_ALREADY_EXISTS)) { logger.debug(dev, "Foreign key for table '{}' already exists. Error code: {}.", entity.getName(), ex.getSQLState()); @@ -693,14 +644,6 @@ protected void addFks(final DbEntity entity, Set fks) throws DatabaseEngin ex.getSQLState() ), ex); } - } finally { - try { - if (alterTableStmt != null) { - alterTableStmt.close(); - } - } catch (final Exception e) { - logger.trace("Error closing statement.", e); - } } } } @@ -832,4 +775,46 @@ protected ResultIterator createResultIterator(PreparedStatement ps) throws Datab protected QueryExceptionHandler getQueryExceptionHandler() { return PG_QUERY_EXCEPTION_HANDLER; } + + /** + * Helper method that logs the time while the Postgres {@link Statement update query} is being executed. + *
+ * This will help identify cases via logs where Postgres database is already locked due to an external query being + * executed and the current one is waiting for that one to finish first. + * + * @param query The query in {@link String} format which will be executed. + * @throws SQLException If the {@link Statement query} fails during its execution. + * @implNote It prints a log every 5 minutes so the user is aware that the query is still being executed. + */ + private int executeUpdateQuery(final String query) throws SQLException { + final long startMilliSeconds = System.currentTimeMillis(); + final Runnable printLog = () -> { + long timePassedMin = Duration.ofMillis(System.currentTimeMillis()).minusMillis(startMilliSeconds).toMinutes(); + this.logger.info("Database is still executing for '{}'min a query.\n" + + "Are you sure the Database is not blocked due to another query being executed?", + timePassedMin + ); + this.logger.trace("The query still being executed for '{}'min is: '{}'.\n", timePassedMin, query); + }; + final ScheduledFuture scheduledFutureLog = this.executor.scheduleAtFixedRate(printLog, 5L, 5L, TimeUnit.MINUTES); + + Statement statement = null; + try { + statement = this.conn.createStatement(); + return statement.executeUpdate(query); + } catch (final SQLException ex) { + throw ex; + } catch (final Exception ex) { + throw new RuntimeException(ex); + } finally { + try { + if (statement != null) { + statement.close(); + } + } catch (final Exception e) { + logger.trace("Error closing statement.", e); + } + scheduledFutureLog.cancel(true); + } + } }