diff --git a/src/main/java/net/helenus/core/AbstractSessionOperations.java b/src/main/java/net/helenus/core/AbstractSessionOperations.java index 15abfae..0a1b3fd 100644 --- a/src/main/java/net/helenus/core/AbstractSessionOperations.java +++ b/src/main/java/net/helenus/core/AbstractSessionOperations.java @@ -60,7 +60,7 @@ public abstract class AbstractSessionOperations { public PreparedStatement prepare(RegularStatement statement) { try { - log(statement, false); + log(statement, null, false); return currentSession().prepare(statement); } catch (RuntimeException e) { throw translateException(e); @@ -69,29 +69,41 @@ public abstract class AbstractSessionOperations { public ListenableFuture prepareAsync(RegularStatement statement) { try { - log(statement, false); + log(statement, null, false); return currentSession().prepareAsync(statement); } catch (RuntimeException e) { throw translateException(e); } } - public ResultSet execute(Statement statement, boolean showValues) { - return executeAsync(statement, showValues).getUninterruptibly(); + public ResultSet execute(Statement statement, boolean showValues) { + return execute(statement, null, showValues); + } + + public ResultSet execute(Statement statement, UnitOfWork uow, boolean showValues) { + return executeAsync(statement, uow, showValues).getUninterruptibly(); } - public ResultSetFuture executeAsync(Statement statement, boolean showValues) { - try { - log(statement, showValues); + public ResultSetFuture executeAsync(Statement statement, boolean showValues) { + return executeAsync(statement, null, showValues); + } + + public ResultSetFuture executeAsync(Statement statement, UnitOfWork uow, boolean showValues) { + try { + log(statement, uow, showValues); return currentSession().executeAsync(statement); } catch (RuntimeException e) { throw translateException(e); } } - void log(Statement statement, boolean showValues) { + void log(Statement statement, UnitOfWork uow, boolean showValues) { if (LOG.isInfoEnabled()) { - LOG.info("Execute statement " + statement); + String uowString = ""; + if (uow != null) { + uowString = "within UOW(" + uow.hashCode() + "): "; + } + LOG.info(String.format("Execute statement %s%s", uowString, statement)); } if (isShowCql()) { if (statement instanceof BuiltStatement) { diff --git a/src/main/java/net/helenus/core/AbstractUnitOfWork.java b/src/main/java/net/helenus/core/AbstractUnitOfWork.java index 641610b..b3434a1 100644 --- a/src/main/java/net/helenus/core/AbstractUnitOfWork.java +++ b/src/main/java/net/helenus/core/AbstractUnitOfWork.java @@ -34,7 +34,7 @@ import net.helenus.core.cache.Facet; /** Encapsulates the concept of a "transaction" as a unit-of-work. */ public abstract class AbstractUnitOfWork implements UnitOfWork, AutoCloseable { - private static final Logger LOG = LoggerFactory.getLogger(AbstractUnitOfWork.class); + private static final Logger LOG = LoggerFactory.getLogger(AbstractUnitOfWork.class); private final List> nested = new ArrayList<>(); private final HelenusSession session; @@ -44,13 +44,13 @@ public abstract class AbstractUnitOfWork implements UnitOfW private List postCommit = new ArrayList(); private boolean aborted = false; private boolean committed = false; - private String purpose; - private int cacheHits = 0; - private int cacheMisses = 0; - private int databaseLookups = 0; - private Stopwatch elapsedTime; - private Stopwatch databaseTime = Stopwatch.createUnstarted(); - private Stopwatch cacheLookupTime = Stopwatch.createUnstarted(); + protected String purpose; + protected int cacheHits = 0; + protected int cacheMisses = 0; + protected int databaseLookups = 0; + protected Stopwatch elapsedTime; + protected Stopwatch databaseTime = Stopwatch.createUnstarted(); + protected Stopwatch cacheLookupTime = Stopwatch.createUnstarted(); protected AbstractUnitOfWork(HelenusSession session, AbstractUnitOfWork parent) { Objects.requireNonNull(session, "containing session cannot be null"); @@ -101,7 +101,7 @@ public abstract class AbstractUnitOfWork implements UnitOfW } } - public void logTimers(String what) { + public String logTimers(String what) { double e = (double) elapsedTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0; double d = (double) databaseTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0; double c = (double) cacheLookupTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0; @@ -110,11 +110,11 @@ public abstract class AbstractUnitOfWork implements UnitOfW double dat = d + c; double daf = (dat / e) * 100; String nested = this.nested.stream().map(uow -> String.valueOf(uow.hashCode())).collect(Collectors.joining(", ")); - LOG.info(String.format("UOW(%s%s) %s (total: %.3fms cache: %.3fms %2.2f%% (%d hit, %d miss) %d database operation%s took %.3fms %2.2f%% [%.3fms %2.2f%%])%s", + return String.format(Locale.US, "UOW(%s%s) %s (total: %,.3fms cache: %,.3fms %,2.2f%% (%,d hit, %,d miss) %,d database operation%s took %,.3fms %,2.2f%% [%,.3fms %,2.2f%%])%s", hashCode(), (this.nested.size() > 0 ? ", [" + nested + "]" : ""), what, e, c, fc, cacheHits, cacheMisses, databaseLookups, (databaseLookups > 1) ? "s" : "", - d, fd, dat, daf, (purpose == null ? "" : " in " + purpose))); + d, fd, dat, daf, (purpose == null ? "" : " in " + purpose)); } private void applyPostCommitFunctions() { @@ -123,7 +123,9 @@ public abstract class AbstractUnitOfWork implements UnitOfW f.apply(); } } - logTimers("committed"); + if (LOG.isInfoEnabled()) { + LOG.info(logTimers("committed")); + } } @Override @@ -235,7 +237,9 @@ public abstract class AbstractUnitOfWork implements UnitOfW // cache.invalidateSince(txn::start time) if (!hasAborted()) { elapsedTime.stop(); - logTimers("aborted"); + if (LOG.isInfoEnabled()) { + LOG.info(logTimers("aborted")); + } } } diff --git a/src/main/java/net/helenus/core/HelenusSession.java b/src/main/java/net/helenus/core/HelenusSession.java index f458080..5df40fb 100644 --- a/src/main/java/net/helenus/core/HelenusSession.java +++ b/src/main/java/net/helenus/core/HelenusSession.java @@ -51,10 +51,14 @@ import net.helenus.support.Fun.Tuple2; import net.helenus.support.Fun.Tuple6; import net.helenus.support.HelenusException; import net.helenus.support.HelenusMappingException; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; public final class HelenusSession extends AbstractSessionOperations implements Closeable { - private final int MAX_CACHE_SIZE = 10000; + private static final Logger LOG = LoggerFactory.getLogger(HelenusSession.class); + + private final int MAX_CACHE_SIZE = 10000; private final int MAX_CACHE_EXPIRE_SECONDS = 600; private final Session session; @@ -293,25 +297,30 @@ public final class HelenusSession extends AbstractSessionOperations implements C } public synchronized UnitOfWork begin(UnitOfWork parent) { - StackTraceElement[] trace = Thread.currentThread().getStackTrace(); - int frame = 2; - if (trace[2].getMethodName().equals("begin")) { - frame = 3; + StringBuilder purpose = null; + if (LOG.isInfoEnabled()) { + StackTraceElement[] trace = Thread.currentThread().getStackTrace(); + int frame = 2; + if (trace[2].getMethodName().equals("begin")) { + frame = 3; + } + purpose = new StringBuilder() + .append(trace[frame].getClassName()) + .append(".") + .append(trace[frame].getMethodName()) + .append("(") + .append(trace[frame].getFileName()) + .append(":") + .append(trace[frame].getLineNumber()) + .append(")"); } - StringBuilder purpose = new StringBuilder() - .append(trace[frame].getClassName()) - .append(".") - .append(trace[frame].getMethodName()) - .append("(") - .append(trace[frame].getFileName()) - .append(":") - .append(trace[frame].getLineNumber()) - .append(")"); try { Class clazz = unitOfWorkClass; Constructor ctor = clazz.getConstructor(HelenusSession.class, UnitOfWork.class); UnitOfWork uow = ctor.newInstance(this, parent); - uow.setPurpose(purpose.toString()); + if (LOG.isInfoEnabled()) { + uow.setPurpose(purpose.toString()); + } if (parent != null) { parent.addNestedUnitOfWork(uow); } diff --git a/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java b/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java index 44a60d3..e0315de 100644 --- a/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java +++ b/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java @@ -353,8 +353,10 @@ public abstract class AbstractStatementOperation { timer = uow.getExecutionTimer(); timer.start(); } - ResultSetFuture futureResultSet = session.executeAsync(statement, showValues); + ResultSetFuture futureResultSet = session.executeAsync(statement, uow, showValues); if (uow != null) uow.record(0, 1); ResultSet resultSet = futureResultSet.getUninterruptibly(); // TODO(gburd): (timeout, units);