Skip to content

Commit

Permalink
Merge pull request #301 from lightblue-platform/logperf
Browse files Browse the repository at this point in the history 
Generating method call string only when needed (i.e. when there is an…
  • Loading branch information
@bserdar
bserdar committed Feb 4, 2016
2 parents 9d7aac5 + efa8ac1 commit 5e00bc1
Show file tree
Hide file tree
Showing 10 changed files with 291 additions and 173 deletions.
12 changes: 9 additions & 3 deletions facade/src/main/java/com/redhat/lightblue/migrator/facade/ConsistencyChecker.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,8 @@
import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.ObjectWriter;
import com.redhat.lightblue.migrator.facade.methodcallstringifier.LazyMethodCallStringifier;
import com.redhat.lightblue.migrator.facade.methodcallstringifier.MethodCallStringifier;

/**
* This class checks for data inconsistencies and handles logging.
Expand Down Expand Up @@ -110,13 +112,17 @@ protected boolean checkConsistency(Object o1, Object o2) {
* @param callToLogInCaseOfInconsistency the call including parameters
* @return
*/
protected boolean checkConsistency(final Object legacyEntity, final Object lightblueEntity, String methodName, String callToLogInCaseOfInconsistency) {
protected boolean checkConsistency(final Object legacyEntity, final Object lightblueEntity, String methodName, MethodCallStringifier callToLogInCaseOfInconsistency) {
if (legacyEntity==null&&lightblueEntity==null) {
return true;
}

String legacyJson=null;
String lightblueJson=null;

if (callToLogInCaseOfInconsistency == null)
callToLogInCaseOfInconsistency = new LazyMethodCallStringifier();

try {
long t1 = System.currentTimeMillis();
legacyJson = getObjectWriter(methodName).writeValueAsString(legacyEntity);
Expand All @@ -130,14 +136,14 @@ protected boolean checkConsistency(final Object legacyEntity, final Object light
log.debug("Consistency check passed: "+ result.passed());
}
if (!result.passed()) {
logInconsistency(callToLogInCaseOfInconsistency, legacyJson, lightblueJson, result.getMessage().replaceAll("\n", ","));
logInconsistency(callToLogInCaseOfInconsistency.toString(), legacyJson, lightblueJson, result.getMessage().replaceAll("\n", ","));
}
return result.passed();
} catch (JSONException e) {
if (legacyEntity!=null&&legacyEntity.equals(lightblueEntity)) {
return true;
} else {
logInconsistency(callToLogInCaseOfInconsistency, legacyJson, lightblueJson, null);
logInconsistency(callToLogInCaseOfInconsistency.toString(), legacyJson, lightblueJson, null);
}
} catch (JsonProcessingException e) {
log.error("Consistency check failed in "+implementationName+"."+callToLogInCaseOfInconsistency+"! Invalid JSON: legacyJson="+legacyJson+", lightblueJson="+lightblueJson, e);
Expand Down
59 changes: 11 additions & 48 deletions facade/src/main/java/com/redhat/lightblue/migrator/facade/DAOFacadeBase.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
import com.google.common.util.concurrent.ListenableFuture;
import com.google.common.util.concurrent.ListeningExecutorService;
import com.google.common.util.concurrent.MoreExecutors;
import com.redhat.lightblue.migrator.facade.methodcallstringifier.EagerMethodCallStringifier;
import com.redhat.lightblue.migrator.features.LightblueMigration;
import com.redhat.lightblue.migrator.features.TogglzRandomUsername;

Expand Down Expand Up @@ -114,44 +115,6 @@ private Class[] toClasses(Object[] objects) {
return classes.toArray(new Class[]{});
}

static String methodCallToString(String methodName, Object[] values) {
try {
StringBuilder str = new StringBuilder();
str.append(methodName).append("(");
Iterator<Object> it = Arrays.asList(values).iterator();
while(it.hasNext()) {
Object value = it.next();
if (value != null && value.getClass().isArray())
if (value.getClass().getComponentType().isPrimitive()) {
// this is an array of primitives, convert to a meaningful string using reflection
String primitiveArrayType = value.getClass().getComponentType().getName();

StringBuilder pStr = new StringBuilder();
for (int i = 0; i < Array.getLength(value); i ++) {
pStr.append(Array.get(value, i));
if (i != Array.getLength(value)-1) {
pStr.append(", ");
}
}
str.append(primitiveArrayType).append("[").append(pStr.toString()).append("]");
}
else {
str.append(Arrays.deepToString((Object[])value));
}
else
str.append(value);
if (it.hasNext()) {
str.append(", ");
}
}
str.append(")");
return str.toString();
} catch (Exception e) {
log.error("Creating method call string failed", e);
return "<creating method call string failed>";
}
}

private <T> ListenableFuture<T> callLightblueDAO(final boolean passIds, final Method method, final Object[] values) {
ListeningExecutorService executor = createExecutor();
try {
Expand Down Expand Up @@ -204,7 +167,7 @@ private Throwable extractUnderlyingException(Throwable t) {
*/
public <T> T callDAOReadMethod(final Class<T> returnedType, final String methodName, final Class[] types, final Object ... values) throws Throwable {
if (log.isDebugEnabled())
log.debug("Calling {}.{} ({} {})", implementationName, methodCallToString(methodName, values), "parallel", "READ");
log.debug("Calling {}.{} ({} {})", implementationName, EagerMethodCallStringifier.stringifyMethodCall(methodName, values), "parallel", "READ");
TogglzRandomUsername.init();

T legacyEntity = null, lightblueEntity = null;
Expand Down Expand Up @@ -236,7 +199,7 @@ public <T> T callDAOReadMethod(final Class<T> returnedType, final String methodN
lightblueEntity = getWithTimeout(listenableFuture, methodName, LightblueMigration.shouldReadSourceEntity());
} catch (TimeoutException te) {
if (LightblueMigration.shouldReadSourceEntity()) {
log.warn("Lightblue call "+implementationName+"."+methodCallToString(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
log.warn("Lightblue call "+implementationName+"."+EagerMethodCallStringifier.stringifyMethodCall(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
return legacyEntity;
} else {
throw te;
Expand All @@ -254,7 +217,7 @@ public <T> T callDAOReadMethod(final Class<T> returnedType, final String methodN
if (LightblueMigration.shouldCheckReadConsistency() && LightblueMigration.shouldReadSourceEntity() && LightblueMigration.shouldReadDestinationEntity()) {
// make sure that response from lightblue and oracle are the same
log.debug("."+methodName+" checking returned entity's consistency");
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, methodCallToString(methodName, values))) {
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, new EagerMethodCallStringifier(methodName, values))) {
// return lightblue data if they are
return lightblueEntity;
} else {
Expand Down Expand Up @@ -296,7 +259,7 @@ public <T> T callDAOReadMethod(final Class<T> returnedType, final String methodN
*/
public <T> T callDAOUpdateMethod(final Class<T> returnedType, final String methodName, final Class[] types, final Object ... values) throws Throwable {
if (log.isDebugEnabled())
log.debug("Calling {}.{} ({} {})", implementationName, methodCallToString(methodName, values), "parallel", "WRITE");
log.debug("Calling {}.{} ({} {})", implementationName, EagerMethodCallStringifier.stringifyMethodCall(methodName, values), "parallel", "WRITE");
TogglzRandomUsername.init();

T legacyEntity = null, lightblueEntity = null;
Expand Down Expand Up @@ -328,7 +291,7 @@ public <T> T callDAOUpdateMethod(final Class<T> returnedType, final String metho
lightblueEntity = getWithTimeout(listenableFuture, methodName, LightblueMigration.shouldWriteSourceEntity());
} catch (TimeoutException te) {
if (LightblueMigration.shouldReadSourceEntity()) {
log.warn("Lightblue call "+implementationName+"."+methodCallToString(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
log.warn("Lightblue call "+implementationName+"."+EagerMethodCallStringifier.stringifyMethodCall(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
return legacyEntity;
} else {
throw te;
Expand All @@ -346,7 +309,7 @@ public <T> T callDAOUpdateMethod(final Class<T> returnedType, final String metho
if (LightblueMigration.shouldCheckWriteConsistency() && LightblueMigration.shouldWriteSourceEntity() && LightblueMigration.shouldWriteDestinationEntity()) {
// make sure that response from lightblue and oracle are the same
log.debug("."+methodName+" checking returned entity's consistency");
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, methodCallToString(methodName, values))) {
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, new EagerMethodCallStringifier(methodName, values))) {
// return lightblue data if they are
return lightblueEntity;
} else {
Expand Down Expand Up @@ -383,7 +346,7 @@ public <T> T callDAOUpdateMethod(final Class<T> returnedType, final String metho
*/
public <T> T callDAOCreateSingleMethod(final EntityIdExtractor<T> entityIdExtractor, final Class<T> returnedType, final String methodName, final Class[] types, final Object ... values) throws Throwable {
if (log.isDebugEnabled())
log.debug("Calling {}.{} ({} {})", implementationName, methodCallToString(methodName, values), "serial", "WRITE");
log.debug("Calling {}.{} ({} {})", implementationName, EagerMethodCallStringifier.stringifyMethodCall(methodName, values), "serial", "WRITE");
TogglzRandomUsername.init();

if (entityIdStore != null)
Expand Down Expand Up @@ -432,7 +395,7 @@ public <T> T callDAOCreateSingleMethod(final EntityIdExtractor<T> entityIdExtrac
EntityIdStoreException se = extractEntityIdStoreExceptionIfExists(ee);
if (se != null && !passIds) {
log.warn("Possible data inconsistency in a create-if-not-exists scenario (entity exists in legacy, but does not in lightblue). Method called: "
+ methodCallToString(methodName, values), se);
+ EagerMethodCallStringifier.stringifyMethodCall(methodName, values), se);
return legacyEntity;
}

Expand All @@ -443,7 +406,7 @@ public <T> T callDAOCreateSingleMethod(final EntityIdExtractor<T> entityIdExtrac
}
} catch (TimeoutException te) {
if (LightblueMigration.shouldReadSourceEntity()) {
log.warn("Lightblue call "+implementationName+"."+methodCallToString(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
log.warn("Lightblue call "+implementationName+"."+EagerMethodCallStringifier.stringifyMethodCall(methodName, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
return legacyEntity;
} else {
throw te;
Expand All @@ -464,7 +427,7 @@ public <T> T callDAOCreateSingleMethod(final EntityIdExtractor<T> entityIdExtrac
log.debug("."+methodName+" checking returned entity's consistency");

// check if entities match
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, methodCallToString(methodName, values))) {
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, new EagerMethodCallStringifier(methodName, values))) {
// return lightblue data if they are
return lightblueEntity;
} else {
Expand Down
66 changes: 4 additions & 62 deletions facade/src/main/java/com/redhat/lightblue/migrator/facade/ServiceFacade.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
import com.google.common.util.concurrent.ListenableFuture;
import com.google.common.util.concurrent.ListeningExecutorService;
import com.google.common.util.concurrent.MoreExecutors;
import com.redhat.lightblue.migrator.facade.methodcallstringifier.LazyMethodCallStringifier;
import com.redhat.lightblue.migrator.facade.proxy.FacadeProxyFactory.Secret;
import com.redhat.lightblue.migrator.facade.sharedstore.SharedStore;
import com.redhat.lightblue.migrator.facade.sharedstore.SharedStoreException;
Expand Down Expand Up @@ -123,65 +124,6 @@ private Class[] toClasses(Object[] objects) {
return classes.toArray(new Class[]{});
}

/**
* Return a pretty printed method call.
*
* @param methodName
* @param values
* @return
*/
static String methodCallToString(Method method, Object[] values) {
try {
StringBuilder str = new StringBuilder();
str.append(method.getName()).append("(");
Iterator<Object> it = Arrays.asList(values).iterator();
Iterator<Annotation[]> annotations = Arrays.asList(method.getParameterAnnotations()).iterator();
while(it.hasNext()) {
Object value = it.next();
boolean isSecret = false;
for (Annotation a: annotations.next()) {
if (a instanceof Secret) {
isSecret=true;
break;
}
}

if (isSecret) {
str.append("****");
} else {
if (value != null && value.getClass().isArray())
if (value.getClass().getComponentType().isPrimitive()) {
// this is an array of primitives, convert to a meaningful string using reflection
String primitiveArrayType = value.getClass().getComponentType().getName();

StringBuilder pStr = new StringBuilder();
for (int i = 0; i < Array.getLength(value); i ++) {
pStr.append(Array.get(value, i));
if (i != Array.getLength(value)-1) {
pStr.append(", ");
}
}
str.append(primitiveArrayType).append("[").append(pStr.toString()).append("]");
}
else {
str.append(Arrays.deepToString((Object[])value));
}
else
str.append(value);
}

if (it.hasNext()) {
str.append(", ");
}
}
str.append(")");
return str.toString();
} catch (Exception e) {
log.error("Creating method call string failed", e);
return "<creating method call string failed>";
}
}

private <T> ListenableFuture<T> callLightblueSvc(final boolean passIds, final Method method, final Object[] values) {
ListeningExecutorService executor = createExecutor();
try {
Expand Down Expand Up @@ -282,7 +224,7 @@ public <T> T callSvcMethod(final FacadeOperation facadeOperation, final boolean
final Class[] types = methodCalled.getParameterTypes();

if (log.isDebugEnabled()) {
log.debug("Calling {}.{} ({} {})", implementationName, methodCallToString(methodCalled, values), callInParallel ? "parallel": "serial", facadeOperation);
log.debug("Calling {}.{} ({} {})", implementationName, LazyMethodCallStringifier.stringifyMethodCall(methodCalled, values), callInParallel ? "parallel": "serial", facadeOperation);
}

TogglzRandomUsername.init();
Expand Down Expand Up @@ -336,7 +278,7 @@ public <T> T callSvcMethod(final FacadeOperation facadeOperation, final boolean
}
} catch (TimeoutException te) {
if (shouldSource(facadeOperation)) {
log.warn("Lightblue call "+implementationName+"."+methodCallToString(methodCalled, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
log.warn("Lightblue call "+implementationName+"."+LazyMethodCallStringifier.stringifyMethodCall(methodCalled, values)+" is taking too long (longer than "+timeoutConfiguration.getTimeoutMS(methodName)+"s). Returning data from legacy.");
return legacyEntity;
} else {
throw te;
Expand All @@ -356,7 +298,7 @@ public <T> T callSvcMethod(final FacadeOperation facadeOperation, final boolean
log.debug("."+methodName+" checking returned entity's consistency");

// check if entities match
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, methodCallToString(methodCalled, values))) {
if (getConsistencyChecker().checkConsistency(legacyEntity, lightblueEntity, methodName, new LazyMethodCallStringifier(methodCalled, values))) {
// return lightblue data if they are
return lightblueEntity;
} else {
Expand Down
Loading

0 comments on commit 5e00bc1

Please sign in to comment.