greg/helenus
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Fix up logging a bit. Fix bug where updateCache wasn't properly adding facets that were bound.

Browse source
This commit is contained in:
Greg Burd 2017-10-24 13:40:35 -04:00
parent a1e29c62c8
commit c6b95f12b4
5 changed files with 66 additions and 39 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

24
src/main/java/net/helenus/core/AbstractSessionOperations.java
View file

@ -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,7 +69,7 @@ public abstract class AbstractSessionOperations {
public ListenableFuture<PreparedStatement> prepareAsync(RegularStatement statement) {
try {
log(statement, false);
log(statement, null, false);
return currentSession().prepareAsync(statement);
} catch (RuntimeException e) {
throw translateException(e);
@ -77,21 +77,33 @@ public abstract class AbstractSessionOperations {
}
public ResultSet execute(Statement statement, boolean showValues) {
return executeAsync(statement, showValues).getUninterruptibly();
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) {
return executeAsync(statement, null, showValues);
}
public ResultSetFuture executeAsync(Statement statement, UnitOfWork uow, boolean showValues) {
try {
log(statement, showValues);
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) {

28
src/main/java/net/helenus/core/AbstractUnitOfWork.java
View file

@ -44,13 +44,13 @@ public abstract class AbstractUnitOfWork<E extends Exception> implements UnitOfW
private List<CommitThunk> postCommit = new ArrayList<CommitThunk>();
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<E> parent) {
Objects.requireNonNull(session, "containing session cannot be null");
@ -101,7 +101,7 @@ public abstract class AbstractUnitOfWork<E extends Exception> 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<E extends Exception> 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<E extends Exception> implements UnitOfW
f.apply();
}
}
logTimers("committed");
if (LOG.isInfoEnabled()) {
LOG.info(logTimers("committed"));
}
}
@Override
@ -235,7 +237,9 @@ public abstract class AbstractUnitOfWork<E extends Exception> implements UnitOfW
// cache.invalidateSince(txn::start time)
if (!hasAborted()) {
elapsedTime.stop();
logTimers("aborted");
if (LOG.isInfoEnabled()) {
LOG.info(logTimers("aborted"));
}
}
}

11
src/main/java/net/helenus/core/HelenusSession.java
View file

@ -51,9 +51,13 @@ 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 static final Logger LOG = LoggerFactory.getLogger(HelenusSession.class);
private final int MAX_CACHE_SIZE = 10000;
private final int MAX_CACHE_EXPIRE_SECONDS = 600;
@ -293,12 +297,14 @@ public final class HelenusSession extends AbstractSessionOperations implements C
}
public synchronized UnitOfWork begin(UnitOfWork parent) {
StringBuilder purpose = null;
if (LOG.isInfoEnabled()) {
StackTraceElement[] trace = Thread.currentThread().getStackTrace();
int frame = 2;
if (trace[2].getMethodName().equals("begin")) {
frame = 3;
}
StringBuilder purpose = new StringBuilder()
purpose = new StringBuilder()
.append(trace[frame].getClassName())
.append(".")
.append(trace[frame].getMethodName())
@ -307,11 +313,14 @@ public final class HelenusSession extends AbstractSessionOperations implements C
.append(":")
.append(trace[frame].getLineNumber())
.append(")");
}
try {
Class<? extends UnitOfWork> clazz = unitOfWorkClass;
Constructor<? extends UnitOfWork> ctor = clazz.getConstructor(HelenusSession.class, UnitOfWork.class);
UnitOfWork uow = ctor.newInstance(this, parent);
if (LOG.isInfoEnabled()) {
uow.setPurpose(purpose.toString());
}
if (parent != null) {
parent.addNestedUnitOfWork(uow);
}

4
src/main/java/net/helenus/core/operation/AbstractStatementOperation.java
View file

@ -353,8 +353,10 @@ public abstract class AbstractStatementOperation<E, O extends AbstractStatementO
} else {
binder.setValueForProperty(prop, valueMap.get(prop.getPropertyName()).toString());
}
facets.add(binder.bind());
});
if (binder.isBound()) {
facets.add(binder.bind());
}
}
} else {
facets.add(facet);

2
src/main/java/net/helenus/core/operation/Operation.java
View file

@ -72,7 +72,7 @@ public abstract class Operation<E> {
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);