Skip to content

Commit

Permalink
Add some logs while Postgres queries are being executed
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
Tiago Silva committed Aug 29, 2023
1 parent 46f29b2 commit 573d1c0
Showing 1 changed file with 68 additions and 83 deletions.
151 changes: 68 additions & 83 deletions src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
*
Expand Down Expand Up @@ -236,25 +250,15 @@ 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());
handleOperation(new OperationFault(entity.getName(), OperationFault.Type.TABLE_ALREADY_EXISTS), ex);
} 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);
}
}
}

Expand Down Expand Up @@ -283,25 +287,15 @@ 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());
handleOperation(new OperationFault(entity.getName(), OperationFault.Type.PRIMARY_KEY_ALREADY_EXISTS), ex);
} 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);
}
}
}

Expand Down Expand Up @@ -334,25 +328,15 @@ 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);
handleOperation(new OperationFault(entity.getName(), OperationFault.Type.INDEX_ALREADY_EXISTS), ex);
} 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);
}
}
}
}
Expand Down Expand Up @@ -495,34 +479,22 @@ 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());
handleOperation(new OperationFault(entity.getName(), OperationFault.Type.TABLE_DOES_NOT_EXIST), ex);
} 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<String> removeColumns = new ArrayList<>();
removeColumns.add("ALTER TABLE");
removeColumns.add(quotize(entity.getName()));
Expand All @@ -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);
}
}

}
Expand Down Expand Up @@ -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);
}
}

}
Expand Down Expand Up @@ -678,11 +631,9 @@ protected void addFks(final DbEntity entity, Set<DbFk> 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());
Expand All @@ -693,14 +644,6 @@ protected void addFks(final DbEntity entity, Set<DbFk> fks) throws DatabaseEngin
ex.getSQLState()
), ex);
}
} finally {
try {
if (alterTableStmt != null) {
alterTableStmt.close();
}
} catch (final Exception e) {
logger.trace("Error closing statement.", e);
}
}
}
}
Expand Down Expand Up @@ -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.
* <br>
* 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);
}
}
}

0 comments on commit 573d1c0

Please sign in to comment.