Skip to content

Commit c9ac57f

Browse files
DaveCTurnerDaveCTurner
authored
Add stats for time spent fetching data while searching snapshots (#51866)
This commit builds on #51637, adding tracking of the total time spent fetching data from the blob store. Relates #50999.
1 parent e620d57 commit c9ac57f

File tree

10 files changed

+157
-38
lines changed

10 files changed

+157
-38
lines changed

‎x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/searchablesnapshots/SearchableSnapshotShardStats.java

Lines changed: 64 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
import org.elasticsearch.common.io.stream.StreamInput;
1010
import org.elasticsearch.common.io.stream.StreamOutput;
1111
import org.elasticsearch.common.io.stream.Writeable;
12+
import org.elasticsearch.common.unit.TimeValue;
1213
import org.elasticsearch.common.xcontent.ToXContentObject;
1314
import org.elasticsearch.common.xcontent.XContentBuilder;
1415
import org.elasticsearch.repositories.IndexId;
@@ -134,15 +135,15 @@ public static class CacheIndexInputStats implements Writeable, ToXContentObject
134135
private final Counter contiguousReads;
135136
private final Counter nonContiguousReads;
136137
private final Counter cachedBytesRead;
137-
private final Counter cachedBytesWritten;
138-
private final Counter directBytesRead;
138+
private final TimedCounter cachedBytesWritten;
139+
private final TimedCounter directBytesRead;
139140

140141
public CacheIndexInputStats(String fileName, long fileLength, long openCount, long innerCount, long closeCount,
141142
Counter forwardSmallSeeks, Counter backwardSmallSeeks,
142143
Counter forwardLargeSeeks, Counter backwardLargeSeeks,
143144
Counter contiguousReads, Counter nonContiguousReads,
144-
Counter cachedBytesRead, Counter cachedBytesWritten,
145-
Counter directBytesRead) {
145+
Counter cachedBytesRead, TimedCounter cachedBytesWritten,
146+
TimedCounter directBytesRead) {
146147
this.fileName = fileName;
147148
this.fileLength = fileLength;
148149
this.openCount = openCount;
@@ -172,8 +173,8 @@ public CacheIndexInputStats(String fileName, long fileLength, long openCount, lo
172173
this.contiguousReads = new Counter(in);
173174
this.nonContiguousReads = new Counter(in);
174175
this.cachedBytesRead = new Counter(in);
175-
this.cachedBytesWritten = new Counter(in);
176-
this.directBytesRead = new Counter(in);
176+
this.cachedBytesWritten = new TimedCounter(in);
177+
this.directBytesRead = new TimedCounter(in);
177178
}
178179

179180
@Override
@@ -243,11 +244,11 @@ public Counter getCachedBytesRead() {
243244
return cachedBytesRead;
244245
}
245246

246-
public Counter getCachedBytesWritten() {
247+
public TimedCounter getCachedBytesWritten() {
247248
return cachedBytesWritten;
248249
}
249250

250-
public Counter getDirectBytesRead() {
251+
public TimedCounter getDirectBytesRead() {
251252
return directBytesRead;
252253
}
253254

@@ -347,18 +348,22 @@ public void writeTo(final StreamOutput out) throws IOException {
347348
}
348349

349350
@Override
350-
public XContentBuilder toXContent(XContentBuilder builder, Params params) throws IOException {
351+
public final XContentBuilder toXContent(XContentBuilder builder, Params params) throws IOException {
351352
builder.startObject();
352353
{
353354
builder.field("count", count);
354355
builder.field("sum", total);
355356
builder.field("min", min);
356357
builder.field("max", max);
358+
innerToXContent(builder, params);
357359
}
358360
builder.endObject();
359361
return builder;
360362
}
361363

364+
void innerToXContent(XContentBuilder builder, Params params) throws IOException {
365+
}
366+
362367
public long getCount() {
363368
return count;
364369
}
@@ -395,4 +400,54 @@ public int hashCode() {
395400
return Objects.hash(count, total, min, max);
396401
}
397402
}
403+
404+
public static class TimedCounter extends Counter {
405+
406+
private final long totalNanoseconds;
407+
408+
public TimedCounter(long count, long total, long min, long max, long totalNanoseconds) {
409+
super(count, total, min, max);
410+
this.totalNanoseconds = totalNanoseconds;
411+
}
412+
413+
TimedCounter(StreamInput in) throws IOException {
414+
super(in);
415+
totalNanoseconds = in.readZLong();
416+
}
417+
418+
@Override
419+
public void writeTo(StreamOutput out) throws IOException {
420+
super.writeTo(out);
421+
out.writeZLong(totalNanoseconds);
422+
}
423+
424+
@Override
425+
void innerToXContent(XContentBuilder builder, Params params) throws IOException {
426+
if (builder.humanReadable()) {
427+
builder.field("time", TimeValue.timeValueNanos(totalNanoseconds).toString());
428+
}
429+
builder.field("time_in_nanos", totalNanoseconds);
430+
}
431+
432+
@Override
433+
public boolean equals(Object other) {
434+
if (this == other) {
435+
return true;
436+
}
437+
if (other == null || getClass() != other.getClass()) {
438+
return false;
439+
}
440+
if (super.equals(other) == false) {
441+
return false;
442+
}
443+
TimedCounter that = (TimedCounter) other;
444+
return totalNanoseconds == that.totalNanoseconds;
445+
}
446+
447+
@Override
448+
public int hashCode() {
449+
return Objects.hash(super.hashCode(), totalNanoseconds);
450+
}
451+
}
452+
398453
}

‎x-pack/plugin/core/src/test/java/org/elasticsearch/xpack/core/searchablesnapshots/SearchableSnapshotShardStatsTests.java

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414
import org.elasticsearch.test.AbstractWireSerializingTestCase;
1515
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.CacheIndexInputStats;
1616
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.Counter;
17+
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.TimedCounter;
1718

1819
import java.util.ArrayList;
1920
import java.util.List;
@@ -45,11 +46,15 @@ private CacheIndexInputStats randomCacheIndexInputStats() {
4546
randomCounter(), randomCounter(),
4647
randomCounter(), randomCounter(),
4748
randomCounter(), randomCounter(),
48-
randomCounter(), randomCounter(),
49-
randomCounter());
49+
randomCounter(), randomTimedCounter(),
50+
randomTimedCounter());
5051
}
5152

5253
private Counter randomCounter() {
5354
return new Counter(randomLong(), randomLong(), randomLong(), randomLong());
5455
}
56+
57+
private TimedCounter randomTimedCounter() {
58+
return new TimedCounter(randomLong(), randomLong(), randomLong(), randomLong(), randomLong());
59+
}
5560
}

‎x-pack/plugin/searchable-snapshots/qa/rest/src/test/resources/rest-api-spec/test/stats.yml

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -167,11 +167,15 @@ teardown:
167167
- gte: { indices.docs.shards.0.0.files.0.cached_bytes_written.sum: 0 }
168168
- gte: { indices.docs.shards.0.0.files.0.cached_bytes_written.min: 0 }
169169
- gte: { indices.docs.shards.0.0.files.0.cached_bytes_written.max: 0 }
170+
- gte: { indices.docs.shards.0.0.files.0.cached_bytes_written.time_in_nanos: 0 }
171+
- is_false: indices.docs.shards.0.0.files.0.cached_bytes_written.time
170172

171173
- gte: { indices.docs.shards.0.0.files.0.direct_bytes_read.count: 0 }
172174
- gte: { indices.docs.shards.0.0.files.0.direct_bytes_read.sum: 0 }
173175
- gte: { indices.docs.shards.0.0.files.0.direct_bytes_read.min: 0 }
174176
- gte: { indices.docs.shards.0.0.files.0.direct_bytes_read.max: 0 }
177+
- gte: { indices.docs.shards.0.0.files.0.direct_bytes_read.time_in_nanos: 0 }
178+
- is_false: indices.docs.shards.0.0.files.0.direct_bytes_read.time
175179

176180
- gte: { indices.docs.shards.0.0.files.0.forward_seeks.small.count: 0 }
177181
- gte: { indices.docs.shards.0.0.files.0.forward_seeks.small.sum: 0 }
@@ -190,3 +194,11 @@ teardown:
190194
- gte: { indices.docs.shards.0.0.files.0.backward_seeks.large.sum: 0 }
191195
- gte: { indices.docs.shards.0.0.files.0.backward_seeks.large.min: 0 }
192196
- gte: { indices.docs.shards.0.0.files.0.backward_seeks.large.max: 0 }
197+
198+
- do:
199+
searchable_snapshots.stats:
200+
index: "d*"
201+
human: true
202+
203+
- is_true: indices.docs.shards.0.0.files.0.cached_bytes_written.time
204+
- is_true: indices.docs.shards.0.0.files.0.direct_bytes_read.time

‎x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/SearchableSnapshotRepository.java

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@
3535
import java.util.HashMap;
3636
import java.util.Map;
3737
import java.util.function.Function;
38+
import java.util.function.LongSupplier;
3839
import java.util.function.Supplier;
3940

4041
import static org.elasticsearch.index.IndexModule.INDEX_STORE_TYPE_SETTING;
@@ -74,7 +75,8 @@ public SearchableSnapshotRepository(Repository in) {
7475
blobStoreRepository = (BlobStoreRepository) in;
7576
}
7677

77-
private Directory makeDirectory(IndexSettings indexSettings, ShardPath shardPath, CacheService cacheService) throws IOException {
78+
private Directory makeDirectory(IndexSettings indexSettings, ShardPath shardPath, CacheService cacheService,
79+
LongSupplier currentTimeNanosSupplier) throws IOException {
7880

7981
IndexId indexId = new IndexId(indexSettings.getIndex().getName(), SNAPSHOT_INDEX_ID_SETTING.get(indexSettings.getSettings()));
8082
BlobContainer blobContainer = blobStoreRepository.shardContainer(indexId, shardPath.getShardId().id());
@@ -86,7 +88,8 @@ private Directory makeDirectory(IndexSettings indexSettings, ShardPath shardPath
8688
Directory directory = new SearchableSnapshotDirectory(snapshot, blobContainer);
8789
if (SNAPSHOT_CACHE_ENABLED_SETTING.get(indexSettings.getSettings())) {
8890
final Path cacheDir = shardPath.getDataPath().resolve("snapshots").resolve(snapshotId.getUUID());
89-
directory = new CacheDirectory(directory, cacheService, cacheDir, snapshotId, indexId, shardPath.getShardId());
91+
directory = new CacheDirectory(directory, cacheService, cacheDir, snapshotId, indexId, shardPath.getShardId(),
92+
currentTimeNanosSupplier);
9093
}
9194
directory = new InMemoryNoOpCommitDirectory(directory);
9295

@@ -146,7 +149,8 @@ public Repository create(RepositoryMetaData metaData, Function<String, Factory>
146149
}
147150

148151
public static IndexStorePlugin.DirectoryFactory newDirectoryFactory(final Supplier<RepositoriesService> repositoriesService,
149-
final Supplier<CacheService> cacheService) {
152+
final Supplier<CacheService> cacheService,
153+
final LongSupplier currentTimeNanosSupplier) {
150154
return (indexSettings, shardPath) -> {
151155
final RepositoriesService repositories = repositoriesService.get();
152156
assert repositories != null;
@@ -159,7 +163,7 @@ public static IndexStorePlugin.DirectoryFactory newDirectoryFactory(final Suppli
159163
final CacheService cache = cacheService.get();
160164
assert cache != null;
161165

162-
return ((SearchableSnapshotRepository) repository).makeDirectory(indexSettings, shardPath, cache);
166+
return ((SearchableSnapshotRepository) repository).makeDirectory(indexSettings, shardPath, cache, currentTimeNanosSupplier);
163167
};
164168
}
165169
}

‎x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/SearchableSnapshots.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ public void onRepositoriesModule(RepositoriesModule repositoriesModule) {
106106
@Override
107107
public Map<String, DirectoryFactory> getDirectoryFactories() {
108108
return Map.of(SearchableSnapshotRepository.SNAPSHOT_DIRECTORY_FACTORY_KEY,
109-
SearchableSnapshotRepository.newDirectoryFactory(repositoriesService::get, cacheService::get));
109+
SearchableSnapshotRepository.newDirectoryFactory(repositoriesService::get, cacheService::get, System::nanoTime));
110110
}
111111

112112
@Override

‎x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/action/TransportSearchableSnapshotsStatsAction.java

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@
3030
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats;
3131
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.CacheIndexInputStats;
3232
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.Counter;
33+
import org.elasticsearch.xpack.core.searchablesnapshots.SearchableSnapshotShardStats.TimedCounter;
3334
import org.elasticsearch.xpack.searchablesnapshots.InMemoryNoOpCommitDirectory;
3435
import org.elasticsearch.xpack.searchablesnapshots.cache.CacheDirectory;
3536
import org.elasticsearch.xpack.searchablesnapshots.cache.IndexInputStats;
@@ -122,14 +123,18 @@ private static CacheIndexInputStats toCacheIndexInputStats(final String fileName
122123
toCounter(inputStats.getForwardSmallSeeks()), toCounter(inputStats.getBackwardSmallSeeks()),
123124
toCounter(inputStats.getForwardLargeSeeks()), toCounter(inputStats.getBackwardLargeSeeks()),
124125
toCounter(inputStats.getContiguousReads()), toCounter(inputStats.getNonContiguousReads()),
125-
toCounter(inputStats.getCachedBytesRead()), toCounter(inputStats.getCachedBytesWritten()),
126-
toCounter(inputStats.getDirectBytesRead()));
126+
toCounter(inputStats.getCachedBytesRead()), toTimedCounter(inputStats.getCachedBytesWritten()),
127+
toTimedCounter(inputStats.getDirectBytesRead()));
127128
}
128129

129130
private static Counter toCounter(final IndexInputStats.Counter counter) {
130131
return new Counter(counter.count(), counter.total(), counter.min(), counter.max());
131132
}
132133

134+
private static TimedCounter toTimedCounter(final IndexInputStats.TimedCounter counter) {
135+
return new TimedCounter(counter.count(), counter.total(), counter.min(), counter.max(), counter.totalNanoseconds());
136+
}
137+
133138
@Nullable
134139
private static CacheDirectory unwrap(Directory dir) {
135140
while (dir != null) {

‎x-pack/plugin/searchable-snapshots/src/main/java/org/elasticsearch/xpack/searchablesnapshots/cache/CacheDirectory.java

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
import java.util.Objects;
3535
import java.util.concurrent.atomic.AtomicBoolean;
3636
import java.util.concurrent.atomic.AtomicReference;
37+
import java.util.function.LongSupplier;
3738

3839
/**
3940
* {@link CacheDirectory} uses a {@link CacheService} to cache Lucene files provided by another {@link Directory}.
@@ -49,8 +50,10 @@ public class CacheDirectory extends FilterDirectory {
4950
private final IndexId indexId;
5051
private final ShardId shardId;
5152
private final Path cacheDir;
53+
private final LongSupplier currentTimeNanosSupplier;
5254

53-
public CacheDirectory(Directory in, CacheService cacheService, Path cacheDir, SnapshotId snapshotId, IndexId indexId, ShardId shardId)
55+
public CacheDirectory(Directory in, CacheService cacheService, Path cacheDir, SnapshotId snapshotId, IndexId indexId, ShardId shardId,
56+
LongSupplier currentTimeNanosSupplier)
5457
throws IOException {
5558
super(in);
5659
this.stats = ConcurrentCollections.newConcurrentMapWithAggressiveConcurrency();
@@ -59,6 +62,7 @@ public CacheDirectory(Directory in, CacheService cacheService, Path cacheDir, Sn
5962
this.snapshotId = Objects.requireNonNull(snapshotId);
6063
this.indexId = Objects.requireNonNull(indexId);
6164
this.shardId = Objects.requireNonNull(shardId);
65+
this.currentTimeNanosSupplier = Objects.requireNonNull(currentTimeNanosSupplier);
6266
}
6367

6468
private CacheKey createCacheKey(String fileName) {
@@ -274,6 +278,7 @@ void writeCacheFile(FileChannel fc, long start, long end) throws IOException {
274278
int bytesCopied = 0;
275279
try (IndexInput input = in.openInput(cacheFileReference.getFileName(), ioContext)) {
276280
stats.incrementInnerOpenCount();
281+
final long startTimeNanos = currentTimeNanosSupplier.getAsLong();
277282
if (start > 0) {
278283
input.seek(start);
279284
}
@@ -285,7 +290,8 @@ void writeCacheFile(FileChannel fc, long start, long end) throws IOException {
285290
bytesCopied += size;
286291
remaining -= size;
287292
}
288-
stats.addCachedBytesWritten(bytesCopied);
293+
final long endTimeNanos = currentTimeNanosSupplier.getAsLong();
294+
stats.addCachedBytesWritten(bytesCopied, endTimeNanos - startTimeNanos);
289295
}
290296
}
291297

@@ -336,6 +342,7 @@ private int readDirectly(long start, long end, byte[] buffer, int offset) throws
336342
int bytesCopied = 0;
337343
try (IndexInput input = in.openInput(cacheFileReference.getFileName(), ioContext)) {
338344
stats.incrementInnerOpenCount();
345+
final long startTimeNanos = currentTimeNanosSupplier.getAsLong();
339346
if (start > 0) {
340347
input.seek(start);
341348
}
@@ -347,7 +354,8 @@ private int readDirectly(long start, long end, byte[] buffer, int offset) throws
347354
bytesCopied += len;
348355
remaining -= len;
349356
}
350-
stats.addDirectBytesRead(bytesCopied);
357+
final long endTimeNanos = currentTimeNanosSupplier.getAsLong();
358+
stats.addDirectBytesRead(bytesCopied, endTimeNanos - startTimeNanos);
351359
}
352360
return bytesCopied;
353361
}

0 commit comments

Comments
 (0)