Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add some logs while Postgres queries are being executed #393

Merged
merged 1 commit into from
Aug 29, 2023
Merged

Add some logs while Postgres queries are being executed #393

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
147 changes: 64 additions & 83 deletions src/main/java/com/feedzai/commons/sql/abstraction/engine/impl/PostgreSqlEngine.java
View file
Open in desktop
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,42 @@ 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);
TiagoMSSantos marked this conversation as resolved.
Show resolved Hide resolved

Statement statement = null;
try {
statement = this.conn.createStatement();
return statement.executeUpdate(query);
} finally {
try {
if (statement != null) {
statement.close();
}
} catch (final Exception e) {
logger.trace("Error closing statement.", e);
}
scheduledFutureLog.cancel(true);
}
}
}
Loading