From a1e29c62c82a8908fbf67958a19e104f15850bb8 Mon Sep 17 00:00:00 2001 From: Greg Burd Date: Tue, 24 Oct 2017 11:05:44 -0400 Subject: [PATCH] Improve UOW logging. --- .../net/helenus/core/AbstractUnitOfWork.java | 62 ++++++++------ .../java/net/helenus/core/HelenusSession.java | 19 ++++- .../java/net/helenus/core/UnitOfWork.java | 2 + .../operation/AbstractStatementOperation.java | 9 +-- .../net/helenus/core/operation/Operation.java | 1 + .../helenus/mapping/HelenusMappingEntity.java | 13 ++- .../mapping/annotation/Constraints.java | 81 ++++++++++++------- .../mapping/validator/DistinctValidator.java | 36 +++++++++ .../core/unitofwork/UnitOfWorkTest.java | 7 +- 9 files changed, 162 insertions(+), 68 deletions(-) create mode 100644 src/main/java/net/helenus/mapping/validator/DistinctValidator.java diff --git a/src/main/java/net/helenus/core/AbstractUnitOfWork.java b/src/main/java/net/helenus/core/AbstractUnitOfWork.java index 9a345bc..641610b 100644 --- a/src/main/java/net/helenus/core/AbstractUnitOfWork.java +++ b/src/main/java/net/helenus/core/AbstractUnitOfWork.java @@ -17,6 +17,7 @@ package net.helenus.core; import java.util.*; import java.util.concurrent.TimeUnit; +import java.util.stream.Collectors; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -43,10 +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 Stopwatch elapsedTime_; - private Stopwatch databaseTime_ = Stopwatch.createUnstarted(); - private Stopwatch cacheLookupTime_ = Stopwatch.createUnstarted(); + 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 AbstractUnitOfWork(HelenusSession session, AbstractUnitOfWork parent) { Objects.requireNonNull(session, "containing session cannot be null"); @@ -57,12 +61,12 @@ public abstract class AbstractUnitOfWork implements UnitOfW @Override public Stopwatch getExecutionTimer() { - return databaseTime_; + return databaseTime; } @Override public Stopwatch getCacheLookupTimer() { - return cacheLookupTime_; + return cacheLookupTime; } @Override @@ -74,31 +78,43 @@ public abstract class AbstractUnitOfWork implements UnitOfW @Override public UnitOfWork begin() { - elapsedTime_ = Stopwatch.createStarted(); + elapsedTime = Stopwatch.createStarted(); // log.record(txn::start) return this; } @Override public UnitOfWork setPurpose(String purpose) { - purpose_ = purpose; + this.purpose = purpose; return this; } + @Override + public void record(int cache, int ops) { + if (cache > 0) { + cacheHits += cache; + } else { + cacheMisses += Math.abs(cache); + } + if (ops > 0) { + databaseLookups += ops; + } + } + public void logTimers(String what) { - - cache hit, miss; - multiple calls, sometimes to db, sometimes to cache, sometimes both... - uow.setPurpose(getClass().getSimpleName() + "::" + Thread.currentThread().getStackTrace()[1].getMethodName()); - - - 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; - double fd = (d / (e - c)) * 100.0; - double fc = (c / (e - d)) * 100.0; - LOG.info(String.format("UOW(%s)%s %s (total: %.3fms cache: %.3fms %2.2f%% db: %.3fms %2.2f%%)", hashCode(), - (purpose_ == null ? "" : " " + purpose_), what, e, c, fc, d, fd)); + 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; + double fd = (d / e) * 100.0; + double fc = (c / e) * 100.0; + 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", + hashCode(), + (this.nested.size() > 0 ? ", [" + nested + "]" : ""), + what, e, c, fc, cacheHits, cacheMisses, databaseLookups, (databaseLookups > 1) ? "s" : "", + d, fd, dat, daf, (purpose == null ? "" : " in " + purpose))); } private void applyPostCommitFunctions() { @@ -191,7 +207,7 @@ public abstract class AbstractUnitOfWork implements UnitOfW } else { session.mergeCache(cache); } - elapsedTime_.stop(); + elapsedTime.stop(); // Apply all post-commit functions for if (parent == null) { @@ -218,7 +234,7 @@ public abstract class AbstractUnitOfWork implements UnitOfW // log.record(txn::abort) // cache.invalidateSince(txn::start time) if (!hasAborted()) { - elapsedTime_.stop(); + elapsedTime.stop(); logTimers("aborted"); } } diff --git a/src/main/java/net/helenus/core/HelenusSession.java b/src/main/java/net/helenus/core/HelenusSession.java index b0b0fb1..f458080 100644 --- a/src/main/java/net/helenus/core/HelenusSession.java +++ b/src/main/java/net/helenus/core/HelenusSession.java @@ -288,15 +288,30 @@ public final class HelenusSession extends AbstractSessionOperations implements C return metadata; } - public synchronized UnitOfWork begin() { - return begin(null); + public UnitOfWork begin() { + return this.begin(null); } public synchronized UnitOfWork begin(UnitOfWork parent) { + StackTraceElement[] trace = Thread.currentThread().getStackTrace(); + int frame = 2; + if (trace[2].getMethodName().equals("begin")) { + frame = 3; + } + 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 (parent != null) { parent.addNestedUnitOfWork(uow); } diff --git a/src/main/java/net/helenus/core/UnitOfWork.java b/src/main/java/net/helenus/core/UnitOfWork.java index 6ff3496..96125c3 100644 --- a/src/main/java/net/helenus/core/UnitOfWork.java +++ b/src/main/java/net/helenus/core/UnitOfWork.java @@ -65,4 +65,6 @@ public interface UnitOfWork extends AutoCloseable { Stopwatch getCacheLookupTimer(); + void record(int cache, int ops); + } diff --git a/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java b/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java index dbe8b08..44a60d3 100644 --- a/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java +++ b/src/main/java/net/helenus/core/operation/AbstractStatementOperation.java @@ -21,10 +21,6 @@ import java.util.Map; import java.util.Optional; import java.util.concurrent.TimeUnit; -import net.helenus.mapping.HelenusProperty; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; - import com.datastax.driver.core.ConsistencyLevel; import com.datastax.driver.core.PreparedStatement; import com.datastax.driver.core.RegularStatement; @@ -43,6 +39,7 @@ import net.helenus.core.UnitOfWork; import net.helenus.core.cache.Facet; import net.helenus.core.cache.UnboundFacet; import net.helenus.core.reflect.MapExportable; +import net.helenus.mapping.HelenusProperty; import net.helenus.mapping.value.BeanColumnValueProvider; import net.helenus.support.HelenusException; @@ -326,14 +323,14 @@ public abstract class AbstractStatementOperation { timer.start(); } ResultSetFuture futureResultSet = session.executeAsync(statement, showValues); + if (uow != null) uow.record(0, 1); ResultSet resultSet = futureResultSet.getUninterruptibly(); // TODO(gburd): (timeout, units); if (uow != null) diff --git a/src/main/java/net/helenus/mapping/HelenusMappingEntity.java b/src/main/java/net/helenus/mapping/HelenusMappingEntity.java index 77cd60e..8869761 100644 --- a/src/main/java/net/helenus/mapping/HelenusMappingEntity.java +++ b/src/main/java/net/helenus/mapping/HelenusMappingEntity.java @@ -15,9 +15,11 @@ */ package net.helenus.mapping; +import java.lang.annotation.Annotation; import java.lang.reflect.Method; import java.util.*; +import net.helenus.mapping.validator.DistinctValidator; import org.apache.commons.lang3.ClassUtils; import com.datastax.driver.core.DefaultMetadata; @@ -33,6 +35,8 @@ import net.helenus.core.cache.UnboundFacet; import net.helenus.mapping.annotation.*; import net.helenus.support.HelenusMappingException; +import javax.validation.ConstraintValidator; + public final class HelenusMappingEntity implements HelenusEntity { private final Class iface; @@ -125,10 +129,11 @@ public final class HelenusMappingEntity implements HelenusEntity { facetsBuilder.add(new UnboundFacet(primaryKeyProperties)); primaryKeyProperties = null; } - Index idx = prop.getGetterMethod().getAnnotation(Index.class); - if (idx.distinct()) { - UnboundFacet facet = new UnboundFacet(prop); - facetsBuilder.add(facet); + for (ConstraintValidator constraint : MappingUtil.getValidators(prop.getGetterMethod())) { + if (constraint.getClass().isAssignableFrom(DistinctValidator.class)); + UnboundFacet facet = new UnboundFacet(prop); + facetsBuilder.add(facet); + break; } } } diff --git a/src/main/java/net/helenus/mapping/annotation/Constraints.java b/src/main/java/net/helenus/mapping/annotation/Constraints.java index 5ed755e..1013015 100644 --- a/src/main/java/net/helenus/mapping/annotation/Constraints.java +++ b/src/main/java/net/helenus/mapping/annotation/Constraints.java @@ -222,34 +222,59 @@ public final class Constraints { public @interface UpperCase { } - /** - * Pattern annotation is LowerCase annotation is using to ensure that value is - * upper case before storing it - * - *

- * Can be used only for @java.lang.CharSequence - * - *

- * It does not have effect on selects and data retrieval operations - */ - @Documented - @Retention(RetentionPolicy.RUNTIME) - @Target(value = {ElementType.METHOD, ElementType.ANNOTATION_TYPE}) - @Constraint(validatedBy = PatternValidator.class) - public @interface Pattern { + /** + * Pattern annotation is LowerCase annotation is using to ensure that value is + * upper case before storing it + * + *

+ * Can be used only for @java.lang.CharSequence + * + *

+ * It does not have effect on selects and data retrieval operations + */ + @Documented + @Retention(RetentionPolicy.RUNTIME) + @Target(value = {ElementType.METHOD, ElementType.ANNOTATION_TYPE}) + @Constraint(validatedBy = PatternValidator.class) + public @interface Pattern { - /** - * User defined regex expression to check match of the value - * - * @return Java regex pattern - */ - String value(); + /** + * User defined regex expression to check match of the value + * + * @return Java regex pattern + */ + String value(); - /** - * Regex flags composition - * - * @return Java regex flags - */ - int flags(); - } + /** + * Regex flags composition + * + * @return Java regex flags + */ + int flags(); + } + + /** + * Distinct annotation is used to signal, but not ensure that a value should be + * distinct in the database. + * + *

+ * Can be used only for @java.lang.CharSequence + * + *

+ * It does not have effect on selects and data retrieval operations + */ + @Documented + @Retention(RetentionPolicy.RUNTIME) + @Target(value = {ElementType.METHOD, ElementType.ANNOTATION_TYPE}) + @Constraint(validatedBy = DistinctValidator.class) + public @interface Distinct { + + /** + * User defined Enum to further restrict the items in the set. + * + * @return Java + */ + Class value() default Enum.class; + + } } diff --git a/src/main/java/net/helenus/mapping/validator/DistinctValidator.java b/src/main/java/net/helenus/mapping/validator/DistinctValidator.java new file mode 100644 index 0000000..cedcec9 --- /dev/null +++ b/src/main/java/net/helenus/mapping/validator/DistinctValidator.java @@ -0,0 +1,36 @@ +/* + * Copyright (C) 2015 The Helenus Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package net.helenus.mapping.validator; + +import java.util.regex.Pattern; + +import javax.validation.ConstraintValidator; +import javax.validation.ConstraintValidatorContext; + +import net.helenus.mapping.annotation.Constraints; + +public final class DistinctValidator implements ConstraintValidator { + + @Override + public void initialize(Constraints.Distinct constraintAnnotation) { + } + + @Override + public boolean isValid(CharSequence value, ConstraintValidatorContext context) { + //TODO(gburd): if there is an Enum type supplied, check that value is valid Enum.name() + return true; + } +} diff --git a/src/test/java/net/helenus/test/integration/core/unitofwork/UnitOfWorkTest.java b/src/test/java/net/helenus/test/integration/core/unitofwork/UnitOfWorkTest.java index 27e86bb..ecc048c 100644 --- a/src/test/java/net/helenus/test/integration/core/unitofwork/UnitOfWorkTest.java +++ b/src/test/java/net/helenus/test/integration/core/unitofwork/UnitOfWorkTest.java @@ -24,10 +24,7 @@ import net.helenus.core.Helenus; import net.helenus.core.HelenusSession; import net.helenus.core.UnitOfWork; import net.helenus.core.annotation.Cacheable; -import net.helenus.mapping.annotation.Column; -import net.helenus.mapping.annotation.Index; -import net.helenus.mapping.annotation.PartitionKey; -import net.helenus.mapping.annotation.Table; +import net.helenus.mapping.annotation.*; import net.helenus.test.integration.build.AbstractEmbeddedCassandraTest; import org.junit.Assert; import org.junit.BeforeClass; @@ -39,8 +36,8 @@ interface Widget { @PartitionKey UUID id(); - @Column @Index + @Constraints.Distinct() String name(); }