Repository: usergrid Updated Branches: refs/heads/debug_logging a769f304a -> f25ac99f3
Add Debug logging for per issues Project: http://git-wip-us.apache.org/repos/asf/usergrid/repo Commit: http://git-wip-us.apache.org/repos/asf/usergrid/commit/76e9e942 Tree: http://git-wip-us.apache.org/repos/asf/usergrid/tree/76e9e942 Diff: http://git-wip-us.apache.org/repos/asf/usergrid/diff/76e9e942 Branch: refs/heads/debug_logging Commit: 76e9e942dd824cec09312d52db75230e918d3462 Parents: b93f8d4 Author: Peter Johnson <[email protected]> Authored: Mon Oct 16 16:57:22 2017 -0700 Committer: Peter Johnson <[email protected]> Committed: Mon Oct 16 16:57:22 2017 -0700 ---------------------------------------------------------------------- .../MvccEntitySerializationStrategyV3Impl.java | 20 +++++- .../persistence/core/util/DebugUtils.java | 73 ++++++++++++++++++++ .../index/impl/EsEntityIndexImpl.java | 14 ++++ .../rest/filters/ContentTypeFilter.java | 21 ++++++ .../usergrid/services/AbstractService.java | 22 ++++++ 5 files changed, 148 insertions(+), 2 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/usergrid/blob/76e9e942/stack/corepersistence/collection/src/main/java/org/apache/usergrid/persistence/collection/serialization/impl/MvccEntitySerializationStrategyV3Impl.java ---------------------------------------------------------------------- diff --git a/stack/corepersistence/collection/src/main/java/org/apache/usergrid/persistence/collection/serialization/impl/MvccEntitySerializationStrategyV3Impl.java b/stack/corepersistence/collection/src/main/java/org/apache/usergrid/persistence/collection/serialization/impl/MvccEntitySerializationStrategyV3Impl.java index 438f731..102e1e3 100644 --- a/stack/corepersistence/collection/src/main/java/org/apache/usergrid/persistence/collection/serialization/impl/MvccEntitySerializationStrategyV3Impl.java +++ b/stack/corepersistence/collection/src/main/java/org/apache/usergrid/persistence/collection/serialization/impl/MvccEntitySerializationStrategyV3Impl.java @@ -15,9 +15,11 @@ import com.fasterxml.jackson.annotation.JsonIgnore; import com.fasterxml.jackson.core.JsonFactory; import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.annotation.JsonSerialize; +import com.netflix.astyanax.model.Rows; import com.netflix.astyanax.serializers.StringSerializer; import org.apache.usergrid.persistence.core.datastax.TableDefinition; import org.apache.usergrid.persistence.core.metrics.MetricsFactory; +import org.apache.usergrid.persistence.core.util.DebugUtils; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -183,6 +185,12 @@ public class MvccEntitySerializationStrategyV3Impl implements MvccEntitySerializ scheduler = Schedulers.io(); } + if (DebugUtils.getMessageId() != null) { + log.info("Reading {} keys from entityIds {} ", + rowKeys.size(), + entityIds, + DebugUtils.getLogMessage()); + } final EntitySetImpl entitySetResults = Observable.from( rowKeys ) //buffer our entities per request, then for that buffer, execute the query in parallel (if neccessary) @@ -193,10 +201,12 @@ public class MvccEntitySerializationStrategyV3Impl implements MvccEntitySerializ // if we have more than 1 request return Observable.just( listObservable ).map( scopedRowKeys -> { - try { - return keyspace.prepareQuery( CF_ENTITY_DATA ).getKeySlice( scopedRowKeys ) + Rows<ScopedRowKey<Id>, Boolean> resultRows = + keyspace.prepareQuery( CF_ENTITY_DATA ).getKeySlice( scopedRowKeys ) .withColumnSlice( COL_VALUE ).execute().getResult(); + + return resultRows; } catch ( ConnectionException e ) { throw new CollectionRuntimeException( null, applicationScope, @@ -228,6 +238,12 @@ public class MvccEntitySerializationStrategyV3Impl implements MvccEntitySerializ } ) ).toBlocking().last(); + if (DebugUtils.getMessageId() != null) { + log.info("Read {} rows from Keyspace {} Message-ID={}", + entitySetResults.size(), + keyspace.getKeyspaceName(), + DebugUtils.getLogMessage()); + } return entitySetResults; } http://git-wip-us.apache.org/repos/asf/usergrid/blob/76e9e942/stack/corepersistence/common/src/main/java/org/apache/usergrid/persistence/core/util/DebugUtils.java ---------------------------------------------------------------------- diff --git a/stack/corepersistence/common/src/main/java/org/apache/usergrid/persistence/core/util/DebugUtils.java b/stack/corepersistence/common/src/main/java/org/apache/usergrid/persistence/core/util/DebugUtils.java new file mode 100644 index 0000000..06d848e --- /dev/null +++ b/stack/corepersistence/common/src/main/java/org/apache/usergrid/persistence/core/util/DebugUtils.java @@ -0,0 +1,73 @@ +package org.apache.usergrid.persistence.core.util; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.util.HashMap; +import java.util.UUID; +import java.util.concurrent.TimeUnit; + +/** + * Created by peterajohnson on 10/16/17. + */ +public class DebugUtils { + + private static ThreadLocal<MessageId> MESSAGE = new ThreadLocal<>(); + + public static final Logger logger = LoggerFactory.getLogger( DebugUtils.class ); + + static public void startRequest() { + MESSAGE.set(new MessageId()); + } + + static public void endRequest() { + MESSAGE.set(null); + } + + static public long timeTaken() { + MessageId id = MESSAGE.get(); + if (id == null) { + return -1L; + } + return id.timeTakenMS(); + } + + static public MessageId getMessageId() { + MessageId id = MESSAGE.get(); + return id; + } + + + static public String getLogMessage() { + MessageId id = MESSAGE.get(); + String msg; + if (id == null) { + msg = "MESSAGE_ID=null"; + } else { + msg = id.getLogMessage(); + } + return msg; + } + + + + public static class MessageId { + private UUID uuid = UUID.randomUUID(); + private long startTime = System.nanoTime(); + + MessageId() { + } + + public long timeTakenMS() { + long now = System.nanoTime(); + return TimeUnit.NANOSECONDS.toMillis(now - startTime); + } + + public String getLogMessage() { + return " MESSAGE_ID=" + uuid + " time=" + timeTakenMS() + "ms."; + } + } + +} + + http://git-wip-us.apache.org/repos/asf/usergrid/blob/76e9e942/stack/corepersistence/queryindex/src/main/java/org/apache/usergrid/persistence/index/impl/EsEntityIndexImpl.java ---------------------------------------------------------------------- diff --git a/stack/corepersistence/queryindex/src/main/java/org/apache/usergrid/persistence/index/impl/EsEntityIndexImpl.java b/stack/corepersistence/queryindex/src/main/java/org/apache/usergrid/persistence/index/impl/EsEntityIndexImpl.java index 3d2f576..dfae55a 100644 --- a/stack/corepersistence/queryindex/src/main/java/org/apache/usergrid/persistence/index/impl/EsEntityIndexImpl.java +++ b/stack/corepersistence/queryindex/src/main/java/org/apache/usergrid/persistence/index/impl/EsEntityIndexImpl.java @@ -32,6 +32,7 @@ import org.apache.usergrid.persistence.core.metrics.MetricsFactory; import org.apache.usergrid.persistence.core.metrics.ObservableTimer; import org.apache.usergrid.persistence.core.migration.data.VersionedData; import org.apache.usergrid.persistence.core.scope.ApplicationScope; +import org.apache.usergrid.persistence.core.util.DebugUtils; import org.apache.usergrid.persistence.core.util.Health; import org.apache.usergrid.persistence.core.util.StringUtils; import org.apache.usergrid.persistence.index.*; @@ -431,6 +432,12 @@ public class EsEntityIndexImpl implements EntityIndex,VersionedData { final int limit, final int offset, final Map<String, Class> fieldsWithType, final boolean analyzeOnly ) { + if (logger.isInfoEnabled()) { + logger.info("Start Search query={} {} ", + query, + DebugUtils.getLogMessage()); + } + IndexValidationUtils.validateSearchEdge(searchEdge); Preconditions.checkNotNull(searchTypes, "searchTypes cannot be null"); Preconditions.checkNotNull( query, "query cannot be null" ); @@ -508,6 +515,13 @@ public class EsEntityIndexImpl implements EntityIndex,VersionedData { } finally{ timerContext.stop(); + + if (logger.isInfoEnabled()) { + logger.info("End Search query={} {} ", + query, + DebugUtils.getLogMessage()); + } + } failureMonitor.success(); http://git-wip-us.apache.org/repos/asf/usergrid/blob/76e9e942/stack/rest/src/main/java/org/apache/usergrid/rest/filters/ContentTypeFilter.java ---------------------------------------------------------------------- diff --git a/stack/rest/src/main/java/org/apache/usergrid/rest/filters/ContentTypeFilter.java b/stack/rest/src/main/java/org/apache/usergrid/rest/filters/ContentTypeFilter.java index 90629ef..c9ab2a3 100644 --- a/stack/rest/src/main/java/org/apache/usergrid/rest/filters/ContentTypeFilter.java +++ b/stack/rest/src/main/java/org/apache/usergrid/rest/filters/ContentTypeFilter.java @@ -42,6 +42,7 @@ import javax.ws.rs.HttpMethod; import javax.ws.rs.core.HttpHeaders; import javax.ws.rs.core.MediaType; +import org.apache.usergrid.persistence.core.util.DebugUtils; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.util.Assert; @@ -90,11 +91,31 @@ public class ContentTypeFilter implements Filter { HeaderWrapperRequest newRequest = new HeaderWrapperRequest( origRequest ); newRequest.adapt(); + if (logger.isInfoEnabled()) { + DebugUtils.startRequest(); + logger.info("doFilter Start METHOD {} PATH {} Message-ID={}", + ((HttpServletRequest) request).getMethod(), + ((HttpServletRequest) request).getPathTranslated(), + DebugUtils.getLogMessage()); + } + try { chain.doFilter( newRequest, response ); } catch ( Exception e ) { logger.error("Error in filter", e); } + + long took = DebugUtils.timeTaken(); + if (logger.isInfoEnabled()) { + logger.info("doFilter End METHOD {} PATH {} {}", + ((HttpServletRequest) request).getMethod(), + ((HttpServletRequest) request).getPathTranslated(), + DebugUtils.getLogMessage()); + + if (took > 1000) { + logger.debug("doFilter took more than one second " + DebugUtils.getLogMessage()); + } + } } http://git-wip-us.apache.org/repos/asf/usergrid/blob/76e9e942/stack/services/src/main/java/org/apache/usergrid/services/AbstractService.java ---------------------------------------------------------------------- diff --git a/stack/services/src/main/java/org/apache/usergrid/services/AbstractService.java b/stack/services/src/main/java/org/apache/usergrid/services/AbstractService.java index f60bfdd..da5c3a9 100644 --- a/stack/services/src/main/java/org/apache/usergrid/services/AbstractService.java +++ b/stack/services/src/main/java/org/apache/usergrid/services/AbstractService.java @@ -29,6 +29,7 @@ import org.apache.usergrid.persistence.cache.CacheFactory; import org.apache.usergrid.persistence.core.metrics.MetricsFactory; import org.apache.usergrid.persistence.core.metrics.ObservableTimer; import org.apache.usergrid.persistence.core.rx.RxTaskScheduler; +import org.apache.usergrid.persistence.core.util.DebugUtils; import org.apache.usergrid.persistence.index.exceptions.QueryAnalyzerException; import org.apache.usergrid.security.shiro.utils.LocalShiroCache; import org.apache.usergrid.security.shiro.utils.SubjectUtils; @@ -699,8 +700,20 @@ public abstract class AbstractService implements Service { return null; } + private static ThreadLocal<UUID> MESSAGE_ID = new ThreadLocal<>(); + public ServiceResults invoke( ServiceContext context ) throws Exception { + + + if (logger.isInfoEnabled()) { + logger.info("Invocation start collectionName {} action {} {}", + context.collectionName, + context.action, + DebugUtils.getLogMessage()); + } + + ServiceResults results = null; Timer.Context time = invokeTimer.time(); String metadataType = checkForServiceMetadata( context ); @@ -733,6 +746,15 @@ public abstract class AbstractService implements Service { results = handleEntityCommand(context, results, entityCommand); time.stop(); + + if (logger.isInfoEnabled()) { + logger.info("Invocation end collectionName {} action {} {}", + context.collectionName, + context.action, + DebugUtils.getLogMessage()); + } + + return results; }
