usergrid-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From mdun...@apache.org
Subject [1/2] usergrid git commit: Add Debug logging for per issues
Date Tue, 17 Oct 2017 00:17:07 GMT
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 <pjohnson@apigee.com>
Authored: Mon Oct 16 16:57:22 2017 -0700
Committer: Peter Johnson <pjohnson@apigee.com>
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;
     }
 


Mime
View raw message