Skip to content

Commit 2d64e3d

Browse files
colings86colings86
authored
Adds trace logging to IndicesRequestCache (#34180)
* Adds trace logging to IndicesRequestCache This change adds trace level logging to `IndicesrrequestCache` witht eh primary aim of helping to identify the cause of teh failures in #32827. The cache will log at trace level when a cache hit or miss occurs including the reader version and the cache key. Note that this change adds a `cacheKeyRenderer` whcih supplies a human readable String of the cache key since the actual cache key itself is a `BytesReference` containing the wire protocol serialised form of the request. Logging is also added for the case where a search timeout occurs and fr that reason the cache entry is invalidated. * Adds comment to remaind us to remove cacheKeyRenderer
1 parent d7893fd commit 2d64e3d

File tree

4 files changed

+48
-26
lines changed

4 files changed

+48
-26
lines changed

‎server/src/main/java/org/elasticsearch/indices/IndicesRequestCache.java‎

Lines changed: 15 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,9 @@
2121

2222
import com.carrotsearch.hppc.ObjectHashSet;
2323
import com.carrotsearch.hppc.ObjectSet;
24+
25+
import org.apache.logging.log4j.LogManager;
26+
import org.apache.logging.log4j.Logger;
2427
import org.apache.lucene.index.DirectoryReader;
2528
import org.apache.lucene.index.IndexReader;
2629
import org.apache.lucene.util.Accountable;
@@ -75,6 +78,8 @@ public final class IndicesRequestCache extends AbstractComponent implements Remo
7578
public static final Setting<TimeValue> INDICES_CACHE_QUERY_EXPIRE =
7679
Setting.positiveTimeSetting("indices.requests.cache.expire", new TimeValue(0), Property.NodeScope);
7780

81+
private static final Logger LOGGER = LogManager.getLogger(IndicesRequestCache.class);
82+
7883
private final ConcurrentMap<CleanupKey, Boolean> registeredClosedListeners = ConcurrentCollections.newConcurrentMap();
7984
private final Set<CleanupKey> keysToClean = ConcurrentCollections.newConcurrentSet();
8085
private final ByteSizeValue size;
@@ -109,13 +114,19 @@ public void onRemoval(RemovalNotification<Key, BytesReference> notification) {
109114
notification.getKey().entity.onRemoval(notification);
110115
}
111116

117+
// NORELEASE The cacheKeyRenderer has been added in order to debug
118+
// https://github.com/elastic/elasticsearch/issues/32827, it should be
119+
// removed when this issue is solved
112120
BytesReference getOrCompute(CacheEntity cacheEntity, Supplier<BytesReference> loader,
113-
DirectoryReader reader, BytesReference cacheKey) throws Exception {
121+
DirectoryReader reader, BytesReference cacheKey, Supplier<String> cacheKeyRenderer) throws Exception {
114122
final Key key = new Key(cacheEntity, reader.getVersion(), cacheKey);
115123
Loader cacheLoader = new Loader(cacheEntity, loader);
116124
BytesReference value = cache.computeIfAbsent(key, cacheLoader);
117125
if (cacheLoader.isLoaded()) {
118126
key.entity.onMiss();
127+
if (logger.isTraceEnabled()) {
128+
logger.trace("Cache miss for reader version [{}] and request:\n {}", reader.getVersion(), cacheKeyRenderer.get());
129+
}
119130
// see if its the first time we see this reader, and make sure to register a cleanup key
120131
CleanupKey cleanupKey = new CleanupKey(cacheEntity, reader.getVersion());
121132
if (!registeredClosedListeners.containsKey(cleanupKey)) {
@@ -126,6 +137,9 @@ BytesReference getOrCompute(CacheEntity cacheEntity, Supplier<BytesReference> lo
126137
}
127138
} else {
128139
key.entity.onHit();
140+
if (logger.isTraceEnabled()) {
141+
logger.trace("Cache hit for reader version [{}] and request:\n {}", reader.getVersion(), cacheKeyRenderer.get());
142+
}
129143
}
130144
return value;
131145
}

‎server/src/main/java/org/elasticsearch/indices/IndicesService.java‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1191,7 +1191,9 @@ public void loadIntoContext(ShardSearchRequest request, SearchContext context, Q
11911191
final DirectoryReader directoryReader = context.searcher().getDirectoryReader();
11921192

11931193
boolean[] loadedFromCache = new boolean[] { true };
1194-
BytesReference bytesReference = cacheShardLevelResult(context.indexShard(), directoryReader, request.cacheKey(), out -> {
1194+
BytesReference bytesReference = cacheShardLevelResult(context.indexShard(), directoryReader, request.cacheKey(), () -> {
1195+
return "Shard: " + request.shardId() + "\nSource:\n" + request.source();
1196+
}, out -> {
11951197
queryPhase.execute(context);
11961198
try {
11971199
context.queryResult().writeToNoId(out);
@@ -1217,6 +1219,10 @@ public void loadIntoContext(ShardSearchRequest request, SearchContext context, Q
12171219
// running a search that times out concurrently will likely timeout again if it's run while we have this `stale` result in the
12181220
// cache. One other option is to not cache requests with a timeout at all...
12191221
indicesRequestCache.invalidate(new IndexShardCacheEntity(context.indexShard()), directoryReader, request.cacheKey());
1222+
if (logger.isTraceEnabled()) {
1223+
logger.trace("Query timed out, invalidating cache entry for request on shard [{}]:\n {}", request.shardId(),
1224+
request.source());
1225+
}
12201226
}
12211227
}
12221228

@@ -1232,8 +1238,8 @@ public ByteSizeValue getTotalIndexingBufferBytes() {
12321238
* @param loader loads the data into the cache if needed
12331239
* @return the contents of the cache or the result of calling the loader
12341240
*/
1235-
private BytesReference cacheShardLevelResult(IndexShard shard, DirectoryReader reader, BytesReference cacheKey, Consumer<StreamOutput> loader)
1236-
throws Exception {
1241+
private BytesReference cacheShardLevelResult(IndexShard shard, DirectoryReader reader, BytesReference cacheKey,
1242+
Supplier<String> cacheKeyRenderer, Consumer<StreamOutput> loader) throws Exception {
12371243
IndexShardCacheEntity cacheEntity = new IndexShardCacheEntity(shard);
12381244
Supplier<BytesReference> supplier = () -> {
12391245
/* BytesStreamOutput allows to pass the expected size but by default uses
@@ -1251,7 +1257,7 @@ private BytesReference cacheShardLevelResult(IndexShard shard, DirectoryReader r
12511257
return out.bytes();
12521258
}
12531259
};
1254-
return indicesRequestCache.getOrCompute(cacheEntity, supplier, reader, cacheKey);
1260+
return indicesRequestCache.getOrCompute(cacheEntity, supplier, reader, cacheKey, cacheKeyRenderer);
12551261
}
12561262

12571263
static final class IndexShardCacheEntity extends AbstractIndexShardCacheEntity {

‎server/src/test/java/org/elasticsearch/indices/IndicesRequestCacheIT.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@
3333
import org.elasticsearch.search.aggregations.bucket.histogram.Histogram.Bucket;
3434
import org.elasticsearch.test.ESIntegTestCase;
3535
import org.elasticsearch.test.hamcrest.ElasticsearchAssertions;
36+
import org.elasticsearch.test.junit.annotations.TestLogging;
3637
import org.joda.time.DateTimeZone;
3738

3839
import java.time.ZoneOffset;
@@ -49,6 +50,7 @@
4950
import static org.hamcrest.Matchers.equalTo;
5051
import static org.hamcrest.Matchers.greaterThan;
5152

53+
@TestLogging(value = "org.elasticsearch.indices.IndicesRequestCache:TRACE")
5254
public class IndicesRequestCacheIT extends ESIntegTestCase {
5355

5456
// One of the primary purposes of the query cache is to cache aggs results
@@ -417,8 +419,8 @@ private static void assertCacheState(Client client, String index, long expectedH
417419
.getRequestCache();
418420
// Check the hit count and miss count together so if they are not
419421
// correct we can see both values
420-
assertEquals(Arrays.asList(expectedHits, expectedMisses),
421-
Arrays.asList(requestCacheStats.getHitCount(), requestCacheStats.getMissCount()));
422+
assertEquals(Arrays.asList(expectedHits, expectedMisses, 0L),
423+
Arrays.asList(requestCacheStats.getHitCount(), requestCacheStats.getMissCount(), requestCacheStats.getEvictions()));
422424
}
423425

424426
}

‎server/src/test/java/org/elasticsearch/indices/IndicesRequestCacheTests.java‎

Lines changed: 19 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -31,14 +31,14 @@
3131
import org.apache.lucene.store.Directory;
3232
import org.apache.lucene.util.Accountable;
3333
import org.apache.lucene.util.BytesRef;
34-
import org.elasticsearch.core.internal.io.IOUtils;
3534
import org.elasticsearch.common.bytes.BytesReference;
3635
import org.elasticsearch.common.io.stream.BytesStreamOutput;
3736
import org.elasticsearch.common.lucene.index.ElasticsearchDirectoryReader;
3837
import org.elasticsearch.common.settings.Settings;
3938
import org.elasticsearch.common.unit.ByteSizeValue;
4039
import org.elasticsearch.common.xcontent.XContentHelper;
4140
import org.elasticsearch.common.xcontent.XContentType;
41+
import org.elasticsearch.core.internal.io.IOUtils;
4242
import org.elasticsearch.index.cache.request.ShardRequestCache;
4343
import org.elasticsearch.index.query.TermQueryBuilder;
4444
import org.elasticsearch.index.shard.ShardId;
@@ -68,7 +68,7 @@ public void testBasicOperationsCache() throws Exception {
6868
// initial cache
6969
TestEntity entity = new TestEntity(requestCacheStats, indexShard);
7070
Loader loader = new Loader(reader, 0);
71-
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes);
71+
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
7272
assertEquals("foo", value.streamInput().readString());
7373
assertEquals(0, requestCacheStats.stats().getHitCount());
7474
assertEquals(1, requestCacheStats.stats().getMissCount());
@@ -79,7 +79,7 @@ public void testBasicOperationsCache() throws Exception {
7979
// cache hit
8080
entity = new TestEntity(requestCacheStats, indexShard);
8181
loader = new Loader(reader, 0);
82-
value = cache.getOrCompute(entity, loader, reader, termBytes);
82+
value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
8383
assertEquals("foo", value.streamInput().readString());
8484
assertEquals(1, requestCacheStats.stats().getHitCount());
8585
assertEquals(1, requestCacheStats.stats().getMissCount());
@@ -126,7 +126,7 @@ public void testCacheDifferentReaders() throws Exception {
126126
// initial cache
127127
TestEntity entity = new TestEntity(requestCacheStats, indexShard);
128128
Loader loader = new Loader(reader, 0);
129-
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes);
129+
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
130130
assertEquals("foo", value.streamInput().readString());
131131
assertEquals(0, requestCacheStats.stats().getHitCount());
132132
assertEquals(1, requestCacheStats.stats().getMissCount());
@@ -140,7 +140,7 @@ public void testCacheDifferentReaders() throws Exception {
140140
// cache the second
141141
TestEntity secondEntity = new TestEntity(requestCacheStats, indexShard);
142142
loader = new Loader(secondReader, 0);
143-
value = cache.getOrCompute(entity, loader, secondReader, termBytes);
143+
value = cache.getOrCompute(entity, loader, secondReader, termBytes, () -> termQuery.toString());
144144
assertEquals("bar", value.streamInput().readString());
145145
assertEquals(0, requestCacheStats.stats().getHitCount());
146146
assertEquals(2, requestCacheStats.stats().getMissCount());
@@ -152,7 +152,7 @@ public void testCacheDifferentReaders() throws Exception {
152152

153153
secondEntity = new TestEntity(requestCacheStats, indexShard);
154154
loader = new Loader(secondReader, 0);
155-
value = cache.getOrCompute(secondEntity, loader, secondReader, termBytes);
155+
value = cache.getOrCompute(secondEntity, loader, secondReader, termBytes, () -> termQuery.toString());
156156
assertEquals("bar", value.streamInput().readString());
157157
assertEquals(1, requestCacheStats.stats().getHitCount());
158158
assertEquals(2, requestCacheStats.stats().getMissCount());
@@ -162,7 +162,7 @@ public void testCacheDifferentReaders() throws Exception {
162162

163163
entity = new TestEntity(requestCacheStats, indexShard);
164164
loader = new Loader(reader, 0);
165-
value = cache.getOrCompute(entity, loader, reader, termBytes);
165+
value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
166166
assertEquals("foo", value.streamInput().readString());
167167
assertEquals(2, requestCacheStats.stats().getHitCount());
168168
assertEquals(2, requestCacheStats.stats().getMissCount());
@@ -222,9 +222,9 @@ public void testEviction() throws Exception {
222222
TestEntity secondEntity = new TestEntity(requestCacheStats, indexShard);
223223
Loader secondLoader = new Loader(secondReader, 0);
224224

225-
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes);
225+
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
226226
assertEquals("foo", value1.streamInput().readString());
227-
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes);
227+
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes, () -> termQuery.toString());
228228
assertEquals("bar", value2.streamInput().readString());
229229
size = requestCacheStats.stats().getMemorySize();
230230
IOUtils.close(reader, secondReader, writer, dir, cache);
@@ -257,12 +257,12 @@ public void testEviction() throws Exception {
257257
TestEntity thirddEntity = new TestEntity(requestCacheStats, indexShard);
258258
Loader thirdLoader = new Loader(thirdReader, 0);
259259

260-
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes);
260+
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
261261
assertEquals("foo", value1.streamInput().readString());
262-
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes);
262+
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes, () -> termQuery.toString());
263263
assertEquals("bar", value2.streamInput().readString());
264264
logger.info("Memory size: {}", requestCacheStats.stats().getMemorySize());
265-
BytesReference value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes);
265+
BytesReference value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes, () -> termQuery.toString());
266266
assertEquals("baz", value3.streamInput().readString());
267267
assertEquals(2, cache.count());
268268
assertEquals(1, requestCacheStats.stats().getEvictions());
@@ -298,12 +298,12 @@ public void testClearAllEntityIdentity() throws Exception {
298298
TestEntity thirddEntity = new TestEntity(requestCacheStats, differentIdentity);
299299
Loader thirdLoader = new Loader(thirdReader, 0);
300300

301-
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes);
301+
BytesReference value1 = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
302302
assertEquals("foo", value1.streamInput().readString());
303-
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes);
303+
BytesReference value2 = cache.getOrCompute(secondEntity, secondLoader, secondReader, termBytes, () -> termQuery.toString());
304304
assertEquals("bar", value2.streamInput().readString());
305305
logger.info("Memory size: {}", requestCacheStats.stats().getMemorySize());
306-
BytesReference value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes);
306+
BytesReference value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes, () -> termQuery.toString());
307307
assertEquals("baz", value3.streamInput().readString());
308308
assertEquals(3, cache.count());
309309
final long hitCount = requestCacheStats.stats().getHitCount();
@@ -312,7 +312,7 @@ public void testClearAllEntityIdentity() throws Exception {
312312
cache.cleanCache();
313313
assertEquals(1, cache.count());
314314
// third has not been validated since it's a different identity
315-
value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes);
315+
value3 = cache.getOrCompute(thirddEntity, thirdLoader, thirdReader, termBytes, () -> termQuery.toString());
316316
assertEquals(hitCount + 1, requestCacheStats.stats().getHitCount());
317317
assertEquals("baz", value3.streamInput().readString());
318318

@@ -371,7 +371,7 @@ public void testInvalidate() throws Exception {
371371
// initial cache
372372
TestEntity entity = new TestEntity(requestCacheStats, indexShard);
373373
Loader loader = new Loader(reader, 0);
374-
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes);
374+
BytesReference value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
375375
assertEquals("foo", value.streamInput().readString());
376376
assertEquals(0, requestCacheStats.stats().getHitCount());
377377
assertEquals(1, requestCacheStats.stats().getMissCount());
@@ -382,7 +382,7 @@ public void testInvalidate() throws Exception {
382382
// cache hit
383383
entity = new TestEntity(requestCacheStats, indexShard);
384384
loader = new Loader(reader, 0);
385-
value = cache.getOrCompute(entity, loader, reader, termBytes);
385+
value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
386386
assertEquals("foo", value.streamInput().readString());
387387
assertEquals(1, requestCacheStats.stats().getHitCount());
388388
assertEquals(1, requestCacheStats.stats().getMissCount());
@@ -396,7 +396,7 @@ public void testInvalidate() throws Exception {
396396
entity = new TestEntity(requestCacheStats, indexShard);
397397
loader = new Loader(reader, 0);
398398
cache.invalidate(entity, reader, termBytes);
399-
value = cache.getOrCompute(entity, loader, reader, termBytes);
399+
value = cache.getOrCompute(entity, loader, reader, termBytes, () -> termQuery.toString());
400400
assertEquals("foo", value.streamInput().readString());
401401
assertEquals(1, requestCacheStats.stats().getHitCount());
402402
assertEquals(2, requestCacheStats.stats().getMissCount());

0 commit comments

Comments
 (0)