SONAR-4901 Add profiling logs around ES queries

2 files changed, 40 insertions, 5 deletions

diff --git a/sonar-server/src/main/java/org/sonar/server/rule/RuleRegistry.java b/sonar-server/src/main/java/org/sonar/server/rule/RuleRegistry.java
index ac5ff8ae37e..0f302c116ab 100644
--- a/sonar-server/src/main/java/org/sonar/server/rule/RuleRegistry.java
+++ b/sonar-server/src/main/java/org/sonar/server/rule/RuleRegistry.java
@@ -71,16 +71,15 @@ public class RuleRegistry {
   public void bulkRegisterRules() {
     TimeProfiler profiler = new TimeProfiler();
     DatabaseSession session = sessionFactory.getSession();
-    profiler.start("Rebuilding rules index");
 
+    profiler.start("Rebuilding rules index - query");
     List<Rule> rules = session.getResults(Rule.class);
+    profiler.stop();
 
     try {
       bulkIndex(rules);
     } catch(IOException ioe) {
       throw new IllegalStateException("Unable to index rules", ioe);
-    } finally {
-      profiler.stop();
     }
   }
 
@@ -141,12 +140,17 @@ public class RuleRegistry {
     String[] ids = new String[rules.size()];
     BytesStream[] docs = new BytesStream[rules.size()];
     int index = 0;
+    TimeProfiler profiler = new TimeProfiler();
+    profiler.start("Build rules documents");
     for (Rule rule: rules) {
       ids[index] = rule.getId().toString();
       docs[index] = ruleDocument(rule);
       index ++;
     }
+    profiler.stop();
+    profiler.start("Index rules");
     searchIndex.bulkIndex(INDEX_RULES, TYPE_RULE, ids, docs);
+    profiler.stop();
   }
 
   private XContentBuilder ruleDocument(Rule rule) throws IOException {
diff --git a/sonar-server/src/main/java/org/sonar/server/search/SearchIndex.java b/sonar-server/src/main/java/org/sonar/server/search/SearchIndex.java
index 72a5cc161b7..880abf212a6 100644
--- a/sonar-server/src/main/java/org/sonar/server/search/SearchIndex.java
+++ b/sonar-server/src/main/java/org/sonar/server/search/SearchIndex.java
@@ -26,6 +26,8 @@ import org.elasticsearch.action.admin.indices.exists.indices.IndicesExistsReques
 import org.elasticsearch.action.bulk.BulkItemResponse;
 import org.elasticsearch.action.bulk.BulkRequestBuilder;
 import org.elasticsearch.action.bulk.BulkResponse;
+import org.elasticsearch.action.index.IndexRequestBuilder;
+import org.elasticsearch.action.search.SearchRequestBuilder;
 import org.elasticsearch.action.search.SearchResponse;
 import org.elasticsearch.action.search.SearchType;
 import org.elasticsearch.client.Client;
@@ -36,12 +38,15 @@ import org.elasticsearch.common.unit.TimeValue;
 import org.elasticsearch.search.SearchHit;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.sonar.api.utils.TimeProfiler;
 
 import java.io.IOException;
 import java.net.URL;
 import java.util.List;
 import java.util.concurrent.ExecutionException;
 
+import static java.lang.String.format;
+
 public class SearchIndex {
 
   private static final Logger LOG = LoggerFactory.getLogger(SearchIndex.class);
@@ -72,7 +77,11 @@ public class SearchIndex {
   }
 
   private void internalPut(String index, String type, String id, BytesStream source, boolean refresh) {
-    client.prepareIndex(index, type, id).setSource(source.bytes()).setRefresh(refresh).execute().actionGet();
+    IndexRequestBuilder builder = client.prepareIndex(index, type, id).setSource(source.bytes()).setRefresh(refresh);
+    TimeProfiler profiler = newDebugProfiler();
+    profiler.start(format("put document with id '%s' with type '%s' into index '%s'", id, type, index));
+    builder.execute().actionGet();
+    profiler.stop();
   }
 
   public void bulkIndex(String index, String type, String[] ids, BytesStream[] sources) {
@@ -80,7 +89,9 @@ public class SearchIndex {
     for (int i=0; i<ids.length; i++) {
       builder.add(client.prepareIndex(index, type, ids[i]).setSource(sources[i].bytes()));
     }
+    TimeProfiler profiler = newDebugProfiler();
     try {
+      profiler.start(format("bulk index of %d documents with type '%s' into index '%s'", ids.length, type, index));
       BulkResponse bulkResponse = client.bulk(builder.setRefresh(true).request()).get();
       if (bulkResponse.hasFailures()) {
         // Retry once per failed doc -- ugly
@@ -95,6 +106,8 @@ public class SearchIndex {
       LOG.error("Interrupted during bulk operation", e);
     } catch (ExecutionException e) {
       LOG.error("Execution of bulk operation failed", e);
+    } finally {
+      profiler.stop();
     }
   }
 
@@ -112,18 +125,25 @@ public class SearchIndex {
 
   private void addMapping(String index, String type, String mapping) {
     IndicesAdminClient indices = client.admin().indices();
+    TimeProfiler profiler = newDebugProfiler();
     try {
       if (! indices.exists(new IndicesExistsRequest(index)).get().isExists()) {
+        profiler.start(format("create index '%s'", index));
         indices.prepareCreate(index).execute().actionGet();
       }
     } catch (Exception e) {
       LOG.error("While checking for index existence", e);
+    } finally {
+      profiler.stop();
     }
 
+    profiler.start(format("put mapping on index '%s' for type '%s'", index, type));
     try {
       indices.putMapping(Requests.putMappingRequest(index).type(type).source(mapping)).actionGet();
     } catch(ElasticSearchParseException parseException) {
       throw new IllegalArgumentException("Invalid mapping file", parseException);
+    } finally {
+      profiler.stop();
     }
   }
 
@@ -131,7 +151,11 @@ public class SearchIndex {
     List<String> result = Lists.newArrayList();
     final int scrollTime = 100;
 
-    SearchResponse scrollResp = searchQuery.toBuilder(client).addField("_id")
+    SearchRequestBuilder builder = searchQuery.toBuilder(client);
+    LOG.debug("findDocumentIds" + builder.internalBuilder().toString());
+    TimeProfiler profiler = newDebugProfiler();
+    profiler.start("findDocumentIds");
+    SearchResponse scrollResp = builder.addField("_id")
             .setSearchType(SearchType.SCAN)
             .setScroll(new TimeValue(scrollTime))
             .setSize(searchQuery.scrollSize()).execute().actionGet();
@@ -146,8 +170,15 @@ public class SearchIndex {
         break;
       }
     }
+    profiler.stop();
 
     return result;
   }
 
+  private TimeProfiler newDebugProfiler() {
+    TimeProfiler profiler = new TimeProfiler();
+    profiler.setLogger(LOG);
+    return profiler;
+  }
+
 }