Skip to content

Commit

Permalink
Improve logging performance in Audit* classes, re #12
Browse files Browse the repository at this point in the history
  • Loading branch information
@safris
safris committed Aug 8, 2024
1 parent 6043005 commit 50fe066
Show file tree
Hide file tree
Showing 5 changed files with 102 additions and 68 deletions.
4 changes: 2 additions & 2 deletions src/main/java/org/libj/sql/Audit.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ protected boolean isDebugEnabled() {
* @param sql The SQL log entry to log.
* @param detail The detail log entry to log, which contains the {@code sql} string.
*/
protected void trace(final StatementType statementType, final String sql, final String detail) {
protected void trace(final StatementType statementType, final CharSequence sql, final String detail) {
final Logger logger;
if (detail != null && (logger = logger()) != null)
logger.trace(detail);
Expand All @@ -76,7 +76,7 @@ protected void trace(final StatementType statementType, final String sql, final
* @param detail The detail log entry to log, which contains the {@code sql} string.
* @param exception If an exception has occurred during the invocation of the associated method.
*/
protected void debug(final StatementType statementType, final String sql, final String detail, final Throwable exception) {
protected void debug(final StatementType statementType, final CharSequence sql, final String detail, final Throwable exception) {
final Logger logger;
if (detail != null && (logger = logger()) != null)
logger.debug(detail);
Expand Down
39 changes: 25 additions & 14 deletions src/main/java/org/libj/sql/AuditConnection.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -165,8 +165,6 @@ public AuditConnection(final Connection target) {
/**
* Returns a log entry for the provided parameters.
*
* @param enabled If {@code true}, this method will return a log entry for the provided parameters. Otherwise if {@code false}, this
* method will return {@code null}.
* @param method The name of the method for which the log entry is being created.
* @param newLine If {@code true}, a newline character {@code '\n'} will be appended before the {@code sql} string. If
* {@code false}, no newline character will be appended before the {@code sql} string.
Expand All @@ -187,10 +185,7 @@ public AuditConnection(final Connection target) {
* {@link ResultSet#CLOSE_CURSORS_AT_COMMIT}, or {@code Integer.MIN_VALUE} for the parameter to be omitted.
* @return A log entry for the provided parameters.
*/
protected String log(final boolean enabled, final String method, final boolean newLine, final String sql, final int autoGeneratedKeys, final int[] columnIndexes, final String[] columnNames, final int resultSetType, final int resultSetConcurrency, final int resultSetHoldability) {
if (!enabled)
return null;

protected String log(final String method, final boolean newLine, final String sql, final int autoGeneratedKeys, final int[] columnIndexes, final String[] columnNames, final int resultSetType, final int resultSetConcurrency, final int resultSetHoldability) {
final StringBuilder b = AuditUtil.log(this, method, this, newLine, new StringBuilder(sql));
if (autoGeneratedKeys != Integer.MIN_VALUE) {
b.append(", ").append(autoGeneratedKeys);
Expand Down Expand Up @@ -308,7 +303,9 @@ public PreparedStatement prepareStatement(final String sql) throws SQLException
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "executeQuery", true, sql, Integer.MIN_VALUE, null, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("executeQuery", true, sql, Integer.MIN_VALUE, null, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE));

return wrap(target.prepareStatement(sql), sql);
}

Expand All @@ -335,7 +332,9 @@ public PreparedStatement prepareStatement(final String sql, final int resultSetT
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareStatement", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareStatement", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, Integer.MIN_VALUE));

return wrap(target.prepareStatement(sql, resultSetType, resultSetConcurrency), sql);
}

Expand All @@ -349,7 +348,9 @@ public CallableStatement prepareCall(final String sql, final int resultSetType,
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareCall", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareCall", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, Integer.MIN_VALUE));

return wrap(target.prepareCall(sql, resultSetType, resultSetConcurrency), sql);
}

Expand All @@ -376,7 +377,9 @@ public PreparedStatement prepareStatement(final String sql, final int resultSetT
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareStatement", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, resultSetHoldability), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareStatement", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, resultSetHoldability));

return wrap(target.prepareStatement(sql, resultSetType, resultSetConcurrency, resultSetHoldability), sql);
}

Expand All @@ -390,7 +393,9 @@ public CallableStatement prepareCall(final String sql, final int resultSetType,
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareCall", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, resultSetHoldability), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareCall", true, sql, Integer.MIN_VALUE, null, null, resultSetType, resultSetConcurrency, resultSetHoldability));

return wrap(target.prepareCall(sql, resultSetType, resultSetConcurrency, resultSetHoldability), sql);
}

Expand All @@ -404,7 +409,9 @@ public PreparedStatement prepareStatement(final String sql, final int autoGenera
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareStatement", true, sql, autoGeneratedKeys, null, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareStatement", true, sql, autoGeneratedKeys, null, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE));

return wrap(target.prepareStatement(sql, autoGeneratedKeys), sql);
}

Expand All @@ -418,7 +425,9 @@ public PreparedStatement prepareStatement(final String sql, final int[] columnIn
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareStatement", true, sql, Integer.MIN_VALUE, columnIndexes, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareStatement", true, sql, Integer.MIN_VALUE, columnIndexes, null, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE));

return wrap(target.prepareStatement(sql, columnIndexes), sql);
}

Expand All @@ -432,7 +441,9 @@ public PreparedStatement prepareStatement(final String sql, final String[] colum
if (traceOpenConnections)
openConnections.put(this, new Trace());

trace(null, log(isTraceEnabled(), "prepareStatement", true, sql, Integer.MIN_VALUE, null, columnNames, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE), sql);
if (isTraceEnabled())
trace(null, sql, log("prepareStatement", true, sql, Integer.MIN_VALUE, null, columnNames, Integer.MIN_VALUE, Integer.MIN_VALUE, Integer.MIN_VALUE));

return wrap(target.prepareStatement(sql, columnNames), sql);
}

Expand Down
46 changes: 21 additions & 25 deletions src/main/java/org/libj/sql/AuditPreparedStatement.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -237,7 +237,7 @@ public static PreparedStatement wrapIfDebugEnabled(final PreparedStatement targe
}

private static final DateTimeFormatter dateFormat = DateTimeFormatter.ISO_LOCAL_DATE;
private static final DateTimeFormatter timeFormat = new DateTimeFormatterBuilder().appendPattern("HH:mm:ss").appendFraction(ChronoField.MILLI_OF_SECOND, 0, 6, true).toFormatter();
private static final DateTimeFormatter timeFormat = new DateTimeFormatterBuilder().appendPattern("HH:mm:ss").appendFraction(ChronoField.MILLI_OF_SECOND, 0, 3, true).toFormatter();
private static final DateTimeFormatter timestampFormat = new DateTimeFormatterBuilder().append(dateFormat).appendLiteral(' ').append(timeFormat).toFormatter();
private static final ThreadLocal<DecimalFormat> numberFormat = DecimalFormatter.createDecimalFormat("###############.###############;-###############.###############");

Expand Down Expand Up @@ -266,18 +266,6 @@ protected boolean isDebugEnabled() {
return logger.isDebugEnabled();
}

@Override
protected void trace(final StatementType statementType, final String sql, final String detail) {
if (detail != null)
logger.trace(detail);
}

@Override
protected void debug(final StatementType statementType, final String sql, final String detail, final Throwable exception) {
if (detail != null)
logger.debug(detail);
}

/**
* Adds a parameter with the provided {@code key} and {@code value} to the parameter map maintained in this instance for the purpose
* of audit logging.
Expand Down Expand Up @@ -320,16 +308,22 @@ public PreparedStatement getTarget() {
return (PreparedStatement)super.getTarget();
}

@Override
protected Logger logger() {
return logger;
}

@Override
public ResultSet executeQuery() throws SQLException {
final PreparedStatement statement = getTarget();
int size = -1;
long time = -1;
Throwable exception = null;
final StringBuilder sql = toStringBuilder();
final boolean isDebugEnabled = isDebugEnabled();
try {
final StringBuilder sql = toStringBuilder();
trace(StatementType.QUERY, sql.toString(), log(isTraceEnabled(), "executeQuery", true, toStringBuilder(), Integer.MIN_VALUE, null, null, null, -1));
if (isTraceEnabled())
trace(StatementType.QUERY, sql, log("executeQuery", true, sql, Integer.MIN_VALUE, null, null, null, -1));

if (isDebugEnabled)
time = System.currentTimeMillis();
Expand All @@ -345,8 +339,8 @@ public ResultSet executeQuery() throws SQLException {
throw t;
}
finally {
final StringBuilder sql = toStringBuilder();
debug(StatementType.QUERY, sql.toString(), log(isDebugEnabled, "executeQuery", true, toStringBuilder(), Integer.MIN_VALUE, null, null, size, time), exception);
if (isDebugEnabled)
debug(StatementType.QUERY, sql, log("executeQuery", true, sql, Integer.MIN_VALUE, null, null, size, time), exception);
}
}

Expand All @@ -355,10 +349,11 @@ public int executeUpdate() throws SQLException {
long time = -1;
int count = -1;
Throwable exception = null;
final StringBuilder sql = toStringBuilder();
final boolean isDebugEnabled = isDebugEnabled();
try {
final StringBuilder sql = toStringBuilder();
trace(StatementType.UPDATE, sql.toString(), log(isTraceEnabled(), "executeUpdate", true, toStringBuilder(), Integer.MIN_VALUE, null, null, null, -1));
if (isTraceEnabled())
trace(StatementType.UPDATE, sql, log("executeUpdate", true, sql, Integer.MIN_VALUE, null, null, null, -1));

if (isDebugEnabled)
time = System.currentTimeMillis();
Expand All @@ -370,8 +365,8 @@ public int executeUpdate() throws SQLException {
throw t;
}
finally {
final StringBuilder sql = toStringBuilder();
debug(StatementType.UPDATE, sql.toString(), log(isDebugEnabled, "executeUpdate", true, toStringBuilder(), Integer.MIN_VALUE, null, null, count, time), exception);
if (isDebugEnabled)
debug(StatementType.UPDATE, sql, log("executeUpdate", true, sql, Integer.MIN_VALUE, null, null, count, time), exception);
}
}

Expand Down Expand Up @@ -508,10 +503,11 @@ public boolean execute() throws SQLException {
long time = -1;
boolean result = false;
Throwable exception = null;
final StringBuilder sql = toStringBuilder();
final boolean isDebugEnabled = isDebugEnabled();
try {
final StringBuilder sql = toStringBuilder();
trace(StatementType.MULTIPLE, sql.toString(), log(isTraceEnabled(), "execute", true, toStringBuilder(), Integer.MIN_VALUE, null, null, null, -1));
if (isTraceEnabled())
trace(StatementType.MULTIPLE, sql, log("execute", true, sql, Integer.MIN_VALUE, null, null, null, -1));

if (isDebugEnabled)
time = System.currentTimeMillis();
Expand All @@ -523,8 +519,8 @@ public boolean execute() throws SQLException {
throw t;
}
finally {
final StringBuilder sql = toStringBuilder();
debug(StatementType.MULTIPLE, sql.toString(), log(isDebugEnabled, "execute", true, toStringBuilder(), Integer.MIN_VALUE, null, null, result, time), exception);
if (isDebugEnabled)
debug(StatementType.MULTIPLE, sql, log("execute", true, sql, Integer.MIN_VALUE, null, null, result, time), exception);
}
}

Expand Down
Loading

0 comments on commit 50fe066

Please sign in to comment.