Skip to content

Commit

Permalink
Index shard search slow log (query and fetch), closes elastic#1462.
Browse files Browse the repository at this point in the history
  • Loading branch information
kimchy committed Nov 14, 2011
1 parent b43c8fe commit ed281fb
Show file tree
Hide file tree
Showing 8 changed files with 275 additions and 4 deletions.
16 changes: 16 additions & 0 deletions config/elasticsearch.yml
Original file line number Diff line number Diff line change
Expand Up @@ -319,3 +319,19 @@
#
# See <http://elasticsearch.org/tutorials/2011/08/22/elasticsearch-on-ec2.html>
# for a step-by-step tutorial.


################################## Slow Log ##################################

# Shard level query and fetch threshold logging.

#index.search.slowlog.level: TRACE
#index.search.slowlog.threshold.query.warn: 10s
#index.search.slowlog.threshold.query.info: 5s
#index.search.slowlog.threshold.query.debug: 2s
#index.search.slowlog.threshold.query.trace: 500ms

#index.search.slowlog.threshold.fetch.warn: 1s
#index.search.slowlog.threshold.fetch.info: 800ms
#index.search.slowlog.threshold.fetch.debug: 500ms
#index.search.slowlog.threshold.fetch.trace: 200ms
14 changes: 13 additions & 1 deletion config/logging.yml
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,11 @@ logger:
# discovery
#discovery: TRACE

index.search.slowlog: TRACE, index_search_slow_log_file

additivity:
index.search.slowlog: false

appender:
console:
type: console
Expand All @@ -29,4 +34,11 @@ appender:
layout:
type: pattern
conversionPattern: "[%d{ISO8601}][%-5p][%-25c] %m%n"


index_search_slow_log_file:
type: dailyRollingFile
file: ${path.logs}/${cluster.name}_index_search_slowlog.log
datePattern: "'.'yyyy-MM-dd"
layout:
type: pattern
conversionPattern: "[%d{ISO8601}][%-5p][%-25c] %m%n"
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,7 @@ public static ESLogger getLogger(String loggerName, Settings settings, String...
}

public static ESLogger getLogger(ESLogger parentLogger, String s) {
return getLogger(parentLogger.getName() + s, parentLogger.getPrefix());
return ESLoggerFactory.getLogger(parentLogger.getPrefix(), getLoggerName(parentLogger.getName() + s));
}

public static ESLogger getLogger(String s) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,10 @@
*/
public class TimeValue implements Serializable, Streamable {

public static TimeValue timeValueNanos(long nanos) {
return new TimeValue(nanos, TimeUnit.NANOSECONDS);
}

public static TimeValue timeValueMillis(long millis) {
return new TimeValue(millis, TimeUnit.MILLISECONDS);
}
Expand Down Expand Up @@ -189,7 +193,7 @@ public String format(PeriodType type) {
}

@Override public String toString() {
if (duration < 0 && timeUnit == TimeUnit.MILLISECONDS) {
if (duration < 0) {
return Long.toString(duration);
}
long nanos = nanos();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@

package org.elasticsearch.common.xcontent;

import org.elasticsearch.common.base.Charsets;

import java.io.IOException;
import java.util.ArrayList;
import java.util.Collection;
Expand All @@ -30,6 +32,25 @@
*/
public class XContentHelper {

public static String convertToJson(byte[] data, int offset, int length, boolean reformatJson) throws IOException {
XContentType xContentType = XContentFactory.xContentType(data, offset, length);
if (xContentType == XContentType.JSON && reformatJson) {
return new String(data, offset, length, Charsets.UTF_8);
}
XContentParser parser = null;
try {
parser = XContentFactory.xContent(xContentType).createParser(data, offset, length);
parser.nextToken();
XContentBuilder builder = XContentFactory.jsonBuilder();
builder.copyCurrentStructure(parser);
return builder.string();
} finally {
if (parser != null) {
parser.close();
}
}
}

/**
* Merges the defaults provided as the second parameter into the content of the first. Only does recursive merge
* for inner maps.
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,210 @@
/*
* Licensed to Elastic Search and Shay Banon under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. Elastic Search licenses this
* file to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing,
* software distributed under the License is distributed on an
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
* KIND, either express or implied. See the License for the
* specific language governing permissions and limitations
* under the License.
*/

package org.elasticsearch.index.search.slowlog;

import org.elasticsearch.cluster.metadata.IndexMetaData;
import org.elasticsearch.common.inject.Inject;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.logging.Loggers;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.unit.TimeValue;
import org.elasticsearch.common.xcontent.XContentHelper;
import org.elasticsearch.index.settings.IndexSettings;
import org.elasticsearch.index.settings.IndexSettingsService;
import org.elasticsearch.index.shard.AbstractIndexShardComponent;
import org.elasticsearch.index.shard.ShardId;
import org.elasticsearch.search.internal.SearchContext;

import java.io.IOException;
import java.util.concurrent.TimeUnit;

/**
*/
public class ShardSlowLogSearchService extends AbstractIndexShardComponent {

private boolean reformat;

private long queryWarnThreshold;
private long queryInfoThreshold;
private long queryDebugThreshold;
private long queryTraceThreshold;

private long fetchWarnThreshold;
private long fetchInfoThreshold;
private long fetchDebugThreshold;
private long fetchTraceThreshold;

private String level;

private final ESLogger queryLogger;
private final ESLogger fetchLogger;

static {
IndexMetaData.addDynamicSettings(
"index.search.slowlog.threshold.query.warn",
"index.search.slowlog.threshold.query.info",
"index.search.slowlog.threshold.query.debug",
"index.search.slowlog.threshold.query.trace",
"index.search.slowlog.threshold.fetch.warn",
"index.search.slowlog.threshold.fetch.info",
"index.search.slowlog.threshold.fetch.debug",
"index.search.slowlog.threshold.fetch.trace",
"index.search.slowlog.reformat",
"index.search.slowlog.level"
);
}

class ApplySettings implements IndexSettingsService.Listener {
@Override public void onRefreshSettings(Settings settings) {
long queryWarnThreshold = settings.getAsTime("index.search.slowlog.threshold.query.warn", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.queryWarnThreshold)).nanos();
if (queryWarnThreshold != ShardSlowLogSearchService.this.queryWarnThreshold) {
ShardSlowLogSearchService.this.queryWarnThreshold = queryWarnThreshold;
}
long queryInfoThreshold = settings.getAsTime("index.search.slowlog.threshold.query.info", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.queryInfoThreshold)).nanos();
if (queryInfoThreshold != ShardSlowLogSearchService.this.queryInfoThreshold) {
ShardSlowLogSearchService.this.queryInfoThreshold = queryInfoThreshold;
}
long queryDebugThreshold = settings.getAsTime("index.search.slowlog.threshold.query.debug", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.queryDebugThreshold)).nanos();
if (queryDebugThreshold != ShardSlowLogSearchService.this.queryDebugThreshold) {
ShardSlowLogSearchService.this.queryDebugThreshold = queryDebugThreshold;
}
long queryTraceThreshold = settings.getAsTime("index.search.slowlog.threshold.query.trace", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.queryTraceThreshold)).nanos();
if (queryTraceThreshold != ShardSlowLogSearchService.this.queryTraceThreshold) {
ShardSlowLogSearchService.this.queryTraceThreshold = queryTraceThreshold;
}

long fetchWarnThreshold = settings.getAsTime("index.search.slowlog.threshold.fetch.warn", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.fetchWarnThreshold)).nanos();
if (fetchWarnThreshold != ShardSlowLogSearchService.this.fetchWarnThreshold) {
ShardSlowLogSearchService.this.fetchWarnThreshold = fetchWarnThreshold;
}
long fetchInfoThreshold = settings.getAsTime("index.search.slowlog.threshold.fetch.info", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.fetchInfoThreshold)).nanos();
if (fetchInfoThreshold != ShardSlowLogSearchService.this.fetchInfoThreshold) {
ShardSlowLogSearchService.this.fetchInfoThreshold = fetchInfoThreshold;
}
long fetchDebugThreshold = settings.getAsTime("index.search.slowlog.threshold.fetch.debug", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.fetchDebugThreshold)).nanos();
if (fetchDebugThreshold != ShardSlowLogSearchService.this.fetchDebugThreshold) {
ShardSlowLogSearchService.this.fetchDebugThreshold = fetchDebugThreshold;
}
long fetchTraceThreshold = settings.getAsTime("index.search.slowlog.threshold.fetch.trace", TimeValue.timeValueNanos(ShardSlowLogSearchService.this.fetchTraceThreshold)).nanos();
if (fetchTraceThreshold != ShardSlowLogSearchService.this.fetchTraceThreshold) {
ShardSlowLogSearchService.this.fetchTraceThreshold = fetchTraceThreshold;
}

String level = settings.get("index.search.slowlog.level", ShardSlowLogSearchService.this.level);
if (!level.equals(ShardSlowLogSearchService.this.level)) {
ShardSlowLogSearchService.this.queryLogger.setLevel(level.toUpperCase());
ShardSlowLogSearchService.this.fetchLogger.setLevel(level.toUpperCase());
ShardSlowLogSearchService.this.level = level;
}

boolean reformat = settings.getAsBoolean("index.search.slowlog.reformat", ShardSlowLogSearchService.this.reformat);
if (reformat != ShardSlowLogSearchService.this.reformat) {
ShardSlowLogSearchService.this.reformat = reformat;
}
}
}

@Inject public ShardSlowLogSearchService(ShardId shardId, @IndexSettings Settings indexSettings, IndexSettingsService indexSettingsService) {
super(shardId, indexSettings);

this.reformat = componentSettings.getAsBoolean("reformat", true);

this.queryWarnThreshold = componentSettings.getAsTime("threshold.query.warn", TimeValue.timeValueNanos(-1)).nanos();
this.queryInfoThreshold = componentSettings.getAsTime("threshold.query.info", TimeValue.timeValueNanos(-1)).nanos();
this.queryDebugThreshold = componentSettings.getAsTime("threshold.query.debug", TimeValue.timeValueNanos(-1)).nanos();
this.queryTraceThreshold = componentSettings.getAsTime("threshold.query.trace", TimeValue.timeValueNanos(-1)).nanos();

this.fetchWarnThreshold = componentSettings.getAsTime("threshold.fetch.warn", TimeValue.timeValueNanos(-1)).nanos();
this.fetchInfoThreshold = componentSettings.getAsTime("threshold.fetch.info", TimeValue.timeValueNanos(-1)).nanos();
this.fetchDebugThreshold = componentSettings.getAsTime("threshold.fetch.debug", TimeValue.timeValueNanos(-1)).nanos();
this.fetchTraceThreshold = componentSettings.getAsTime("threshold.fetch.trace", TimeValue.timeValueNanos(-1)).nanos();

this.level = componentSettings.get("level", "TRACE").toUpperCase();

this.queryLogger = Loggers.getLogger(logger, ".query");
this.fetchLogger = Loggers.getLogger(logger, ".fetch");

queryLogger.setLevel(level);
fetchLogger.setLevel(level);

indexSettingsService.addListener(new ApplySettings());
}

public void onQueryPhase(SearchContext context, long tookInNanos) {
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold && queryLogger.isWarnEnabled()) {
queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold && queryLogger.isInfoEnabled()) {
queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold && queryLogger.isDebugEnabled()) {
queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold && queryLogger.isTraceEnabled()) {
queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
}
}

public void onFetchPhase(SearchContext context, long tookInNanos) {
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold && fetchLogger.isWarnEnabled()) {
fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold && fetchLogger.isInfoEnabled()) {
fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold && fetchLogger.isDebugEnabled()) {
fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold && fetchLogger.isTraceEnabled()) {
fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos, reformat));
}
}

public static class SlowLogSearchContextPrinter {
private final SearchContext context;
private final long tookInNanos;
private final boolean reformat;

public SlowLogSearchContextPrinter(SearchContext context, long tookInNanos, boolean reformat) {
this.context = context;
this.tookInNanos = tookInNanos;
this.reformat = reformat;
}

@Override public String toString() {
StringBuilder sb = new StringBuilder();
sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ");
sb.append("search_type[").append(context.searchType()).append("], total_shards[").append(context.numberOfShards()).append("], ");
if (context.request().sourceLength() > 0) {
try {
sb.append("source[").append(XContentHelper.convertToJson(context.request().source(), context.request().sourceOffset(), context.request().sourceLength(), reformat));
} catch (IOException e) {
sb.append("source[_failed_to_convert_], ");
}
} else {
sb.append("source[], ");
}
if (context.request().extraSourceLength() > 0) {
try {
sb.append("extra_source[").append(XContentHelper.convertToJson(context.request().extraSource(), context.request().extraSourceOffset(), context.request().extraSourceLength(), reformat));
} catch (IOException e) {
sb.append("extra_source[_failed_to_convert_], ");
}
} else {
sb.append("extra_source[], ");
}
return sb.toString();
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -20,12 +20,14 @@
package org.elasticsearch.index.search.stats;

import org.elasticsearch.common.inject.AbstractModule;
import org.elasticsearch.index.search.slowlog.ShardSlowLogSearchService;

/**
*/
public class ShardSearchModule extends AbstractModule {

@Override protected void configure() {
bind(ShardSearchService.class).asEagerSingleton();
bind(ShardSlowLogSearchService.class).asEagerSingleton();
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@
import org.elasticsearch.common.metrics.CounterMetric;
import org.elasticsearch.common.metrics.MeanMetric;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.index.search.slowlog.ShardSlowLogSearchService;
import org.elasticsearch.index.settings.IndexSettings;
import org.elasticsearch.index.shard.AbstractIndexShardComponent;
import org.elasticsearch.index.shard.ShardId;
Expand All @@ -38,12 +39,15 @@
*/
public class ShardSearchService extends AbstractIndexShardComponent {

private final ShardSlowLogSearchService slowLogSearchService;

private final StatsHolder totalStats = new StatsHolder();

private volatile Map<String, StatsHolder> groupsStats = ImmutableMap.of();

@Inject public ShardSearchService(ShardId shardId, @IndexSettings Settings indexSettings) {
@Inject public ShardSearchService(ShardId shardId, @IndexSettings Settings indexSettings, ShardSlowLogSearchService slowLogSearchService) {
super(shardId, indexSettings);
this.slowLogSearchService = slowLogSearchService;
}

/**
Expand Down Expand Up @@ -101,6 +105,7 @@ public void onQueryPhase(SearchContext searchContext, long tookInNanos) {
statsHolder.queryCurrent.dec();
}
}
slowLogSearchService.onQueryPhase(searchContext, tookInNanos);
}

public void onPreFetchPhase(SearchContext searchContext) {
Expand Down Expand Up @@ -132,6 +137,7 @@ public void onFetchPhase(SearchContext searchContext, long tookInNanos) {
statsHolder.fetchCurrent.dec();
}
}
slowLogSearchService.onFetchPhase(searchContext, tookInNanos);
}

public void clear() {
Expand Down

0 comments on commit ed281fb

Please sign in to comment.