SONAR-5007 - Added fine-grained timings as debug log level

diff --git a/sonar-server/src/main/java/org/sonar/server/search/BaseIndex.java b/sonar-server/src/main/java/org/sonar/server/search/BaseIndex.java
index aa32d5fc7efb7849de964ef8c09b3cecebd8a208..0fcf9d30d576aeae5eeb185b601b02eac7dd1ff6 100644 (file)
--- a/sonar-server/src/main/java/org/sonar/server/search/BaseIndex.java
+++ b/sonar-server/src/main/java/org/sonar/server/search/BaseIndex.java
@@ -52,6 +52,7 @@ import java.util.Collection;
 import java.util.Date;
 import java.util.HashMap;
 import java.util.Iterator;
+import java.util.List;
 import java.util.Map;
 import java.util.Queue;
 import java.util.concurrent.ExecutionException;
@@ -435,13 +436,25 @@ public abstract class BaseIndex<DOMAIN, DTO extends Dto<KEY>, KEY extends Serial
 
   @Override
   public void upsert(Object obj, KEY key) throws Exception {
-    this.updateDocument(this.normalizer.normalizeNested(obj, key), key);
+    long t0 = System.currentTimeMillis();
+    List<UpdateRequest> requests = this.normalizer.normalizeNested(obj, key);
+    long t1 = System.currentTimeMillis();
+    this.updateDocument(requests, key);
+    long t2 = System.currentTimeMillis();
+    LOG.debug("UPSERT [object] time:{}ms ({}ms normalize, {}ms elastic)",
+      t2-t0, t1-t0, t2-t1);
   }
 
   @Override
   public void upsertByDto(DTO item) {
     try {
-      this.updateDocument(normalizer.normalize(item), item.getKey());
+      long t0 = System.currentTimeMillis();
+      List<UpdateRequest> request = normalizer.normalize(item);
+      long t1 = System.currentTimeMillis();
+      this.updateDocument(request, item.getKey());
+      long t2 = System.currentTimeMillis();
+      LOG.debug("UPSERT [dto] time:{}ms ({}ms normalize, {}ms elastic)",
+        t2-t0, t1-t0, t2-t1);
     } catch (Exception e) {
       LOG.error("Could not update document for index {}: {}",
         this.getIndexName(), e.getMessage(), e);

diff --git a/sonar-server/src/main/java/org/sonar/server/search/IndexQueue.java b/sonar-server/src/main/java/org/sonar/server/search/IndexQueue.java
index 33310328521b4909637bf3fbf04b48db927a8d53..c85e8a9d400824fdd3a8e75d9e88c67f22e2b99b 100644 (file)
--- a/sonar-server/src/main/java/org/sonar/server/search/IndexQueue.java
+++ b/sonar-server/src/main/java/org/sonar/server/search/IndexQueue.java
@@ -22,7 +22,12 @@ package org.sonar.server.search;
 import com.google.common.collect.ArrayListMultimap;
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.LinkedListMultimap;
+import com.google.common.collect.Lists;
 import com.google.common.collect.Multimap;
+import com.google.common.collect.Sets;
+import org.apache.commons.lang.StringUtils;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.sonar.api.ServerComponent;
 import org.sonar.core.cluster.WorkQueue;
 import org.sonar.server.search.action.EmbeddedIndexAction;
@@ -42,7 +47,9 @@ import java.util.concurrent.TimeUnit;
 public class IndexQueue extends LinkedBlockingQueue<Runnable>
   implements ServerComponent, WorkQueue<IndexAction> {
 
-  private static final Integer DEFAULT_QUEUE_SIZE = 20;
+  private static final Logger LOGGER = LoggerFactory.getLogger(IndexQueue.class);
+
+  private static final Integer DEFAULT_QUEUE_SIZE = 200;
 
   public IndexQueue() {
     super(DEFAULT_QUEUE_SIZE);
@@ -56,16 +63,32 @@ public class IndexQueue extends LinkedBlockingQueue<Runnable>
   @Override
   public void enqueue(List<IndexAction> actions) {
 
+    int bcount = 0;
+    int ecount = 0;
+    List<String> refreshes = Lists.newArrayList();
+    Set<String> types = Sets.newHashSet();
+    long all_start = System.currentTimeMillis();
+    long indexTime;
+    long refreshTime;
+    long embeddedTime;
+
     if (actions.size() == 1) {
       /* Atomic update here */
       CountDownLatch latch = new CountDownLatch(1);
       IndexAction action = actions.get(0);
       action.setLatch(latch);
       try {
+        indexTime = System.currentTimeMillis();
         this.offer(action, 1000, TimeUnit.SECONDS);
-        latch.await(1500, TimeUnit.MILLISECONDS);
+        latch.await(1000, TimeUnit.MILLISECONDS);
+        bcount ++;
+        indexTime = System.currentTimeMillis() - indexTime;
         // refresh the index.
+        refreshTime = System.currentTimeMillis();
         action.getIndex().refresh();
+        refreshTime = System.currentTimeMillis() - refreshTime;
+        refreshes.add(action.getIndex().getIndexName());
+        types.add(action.getPayloadClass().getSimpleName());
       } catch (InterruptedException e) {
         throw new IllegalStateException("ES update has been interrupted", e);
       }
@@ -100,33 +123,48 @@ public class IndexQueue extends LinkedBlockingQueue<Runnable>
         /* execute all item actions */
         Multimap<String, IndexAction> itemBulks = makeBulkByType(itemActions);
           CountDownLatch itemLatch = new CountDownLatch(itemBulks.size());
+        indexTime = System.currentTimeMillis();
         for (IndexAction action : itemBulks.values()) {
           action.setLatch(itemLatch);
           this.offer(action, 1000, TimeUnit.SECONDS);
+          types.add(action.getPayloadClass().getSimpleName());
+          bcount++;
+
         }
-        itemLatch.await(1500, TimeUnit.MILLISECONDS);
+        itemLatch.await(2000, TimeUnit.MILLISECONDS);
+        indexTime = System.currentTimeMillis() - indexTime;
 
         /* and now push the embedded */
         CountDownLatch embeddedLatch = new CountDownLatch(embeddedActions.size());
+        embeddedTime = System.currentTimeMillis();
         for (IndexAction action : embeddedActions) {
           action.setLatch(embeddedLatch);
           this.offer(action, 1000, TimeUnit.SECONDS);
+          types.add(action.getPayloadClass().getSimpleName());
+          ecount ++;
         }
         embeddedLatch.await(1500, TimeUnit.MILLISECONDS);
+        embeddedTime = System.currentTimeMillis() - embeddedTime;
 
         /* Finally refresh affected indexes */
         Set<String> refreshedIndexes = new HashSet<String>();
+        refreshTime = System.currentTimeMillis();
         for (IndexAction action : actions) {
           if (action.getIndex() != null &&
             !refreshedIndexes.contains(action.getIndex().getIndexName())){
-            action.getIndex().refresh();
             refreshedIndexes.add(action.getIndex().getIndexName());
+            action.getIndex().refresh();
+            refreshes.add(action.getIndex().getIndexName());
           }
         }
-
+        refreshTime = System.currentTimeMillis() - refreshTime;
       } catch (InterruptedException e) {
         throw new IllegalStateException("ES update has been interrupted", e);
       }
+      LOGGER.debug("INDEX - time:{}ms ({}ms index, {}ms embedded, {}ms refresh)\ttypes:[{}],\tbulk:{}\tembedded:{}\trefresh:[{}]",
+        (System.currentTimeMillis() - all_start), indexTime, embeddedTime, refreshTime,
+        StringUtils.join(types,","),
+        bcount, ecount, StringUtils.join(refreshes, ","));
     }
   }