Improve UOW logging.

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<E extends Exception> implements UnitOfW
 	private List<CommitThunk> postCommit = new ArrayList<CommitThunk>();
 	private boolean aborted = false;
 	private boolean committed = false;
-	private String purpose_;
+	private String purpose;
-	private Stopwatch elapsedTime_;
+	private int cacheHits = 0;
-	private Stopwatch databaseTime_ = Stopwatch.createUnstarted();
+	private int cacheMisses = 0;
-	private Stopwatch cacheLookupTime_ = Stopwatch.createUnstarted();
+	private int databaseLookups = 0;
+	private Stopwatch elapsedTime;
+	private Stopwatch databaseTime = Stopwatch.createUnstarted();
+	private Stopwatch cacheLookupTime = Stopwatch.createUnstarted();
 
 	protected AbstractUnitOfWork(HelenusSession session, AbstractUnitOfWork<E> parent) {
 		Objects.requireNonNull(session, "containing session cannot be null");
@@ -57,12 +61,12 @@ public abstract class AbstractUnitOfWork<E extends Exception> 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<E extends Exception> implements UnitOfW
 
 	@Override
 	public UnitOfWork<E> 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) {
-
+		double e = (double) elapsedTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
-	    cache hit, miss;
+		double d = (double) databaseTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
-        multiple calls, sometimes to db, sometimes to cache, sometimes both...
+		double c = (double) cacheLookupTime.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
-        uow.setPurpose(getClass().getSimpleName() + "::" + Thread.currentThread().getStackTrace()[1].getMethodName());
+		double fd = (d / e) * 100.0;
-
+		double fc = (c / e) * 100.0;
-
+		double dat = d + c;
-		double e = (double) elapsedTime_.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
+		double daf = (dat / e) * 100;
-		double d = (double) databaseTime_.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
+		String nested = this.nested.stream().map(uow -> String.valueOf(uow.hashCode())).collect(Collectors.joining(", "));
-		double c = (double) cacheLookupTime_.elapsed(TimeUnit.MICROSECONDS) / 1000.0;
+		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",
-		double fd = (d / (e - c)) * 100.0;
+                hashCode(),
-		double fc = (c / (e - d)) * 100.0;
+                (this.nested.size() > 0 ? ", [" + nested + "]" : ""),
-		LOG.info(String.format("UOW(%s)%s %s (total: %.3fms cache: %.3fms %2.2f%% db: %.3fms %2.2f%%)", hashCode(),
+				what, e, c, fc, cacheHits, cacheMisses, databaseLookups, (databaseLookups > 1) ? "s" : "",
-				(purpose_ == null ? "" : " " + purpose_), what, e, c, fc, d, fd));
+                d, fd, dat, daf, (purpose == null ? "" : " in " + purpose)));
 	}
 
 	private void applyPostCommitFunctions() {
@@ -191,7 +207,7 @@ public abstract class AbstractUnitOfWork<E extends Exception> 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<E extends Exception> implements UnitOfW
 		// log.record(txn::abort)
 		// cache.invalidateSince(txn::start time)
 		if (!hasAborted()) {
-			elapsedTime_.stop();
+			elapsedTime.stop();
 			logTimers("aborted");
 		}
 	}

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() {
+	public UnitOfWork begin() {
-		return begin(null);
+	    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<? extends UnitOfWork> clazz = unitOfWorkClass;
 			Constructor<? extends UnitOfWork> ctor = clazz.getConstructor(HelenusSession.class, UnitOfWork.class);
 			UnitOfWork uow = ctor.newInstance(this, parent);
+			uow.setPurpose(purpose.toString());
 			if (parent != null) {
 				parent.addNestedUnitOfWork(uow);
 			}

src/main/java/net/helenus/core/UnitOfWork.java

@@ -65,4 +65,6 @@ public interface UnitOfWork<X extends Exception> extends AutoCloseable {
 
 	Stopwatch getCacheLookupTimer();
 
+    void record(int cache, int ops);
+
 }

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<E, O extends AbstractStatementO
 			optionalCachedResult = uow.cacheLookup(facets);
 			if (optionalCachedResult.isPresent()) {
 				uowCacheHits.mark();
-                uow.setCacheHit(true);
+                uow.record(1, 0);
 				result = (E) optionalCachedResult.get();
 			}
 		}
 
 		if (result == null) {
 			uowCacheMiss.mark();
-            uow.setCacheHit(true);
+            uow.record(-1, 0);
 		}
 
 		return result;

src/main/java/net/helenus/core/operation/Operation.java

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

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);
+                    for (ConstraintValidator<?,?> constraint : MappingUtil.getValidators(prop.getGetterMethod())) {
-					if (idx.distinct()) {
+                        if (constraint.getClass().isAssignableFrom(DistinctValidator.class));
-						UnboundFacet facet = new UnboundFacet(prop);
+                        UnboundFacet facet = new UnboundFacet(prop);
-						facetsBuilder.add(facet);
+                        facetsBuilder.add(facet);
+                        break;
 					}
 			}
 		}

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
+     * Pattern annotation is LowerCase annotation is using to ensure that value is
-	 * upper case before storing it
+     * upper case before storing it
-	 *
+     *
-	 * <p>
+     * <p>
-	 * Can be used only for @java.lang.CharSequence
+     * Can be used only for @java.lang.CharSequence
-	 *
+     *
-	 * <p>
+     * <p>
-	 * It does not have effect on selects and data retrieval operations
+     * It does not have effect on selects and data retrieval operations
-	 */
+     */
-	@Documented
+    @Documented
-	@Retention(RetentionPolicy.RUNTIME)
+    @Retention(RetentionPolicy.RUNTIME)
-	@Target(value = {ElementType.METHOD, ElementType.ANNOTATION_TYPE})
+    @Target(value = {ElementType.METHOD, ElementType.ANNOTATION_TYPE})
-	@Constraint(validatedBy = PatternValidator.class)
+    @Constraint(validatedBy = PatternValidator.class)
-	public @interface Pattern {
+    public @interface Pattern {
 
-		/**
+        /**
-		 * User defined regex expression to check match of the value
+         * User defined regex expression to check match of the value
-		 *
+         *
-		 * @return Java regex pattern
+         * @return Java regex pattern
-		 */
+         */
-		String value();
+        String value();
 
-		/**
+        /**
-		 * Regex flags composition
+         * Regex flags composition
-		 *
+         *
-		 * @return Java regex flags
+         * @return Java regex flags
-		 */
+         */
-		int flags();
+        int flags();
-	}
+    }
+
+    /**
+     * Distinct annotation is used to signal, but not ensure that a value should be
+     * distinct in the database.
+     *
+     * <p>
+     * Can be used only for @java.lang.CharSequence
+     *
+     * <p>
+     * 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<? extends Enum> value() default Enum.class;
+
+    }
 }

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<Constraints.Distinct, CharSequence> {
+
+    @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;
+    }
+}

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.*;
-import net.helenus.mapping.annotation.Index;
-import net.helenus.mapping.annotation.PartitionKey;
-import net.helenus.mapping.annotation.Table;
 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();
 }