Improve SegmentMetadataCache visibility #14453

findingrish · 2023-06-20T08:55:40Z

Add metric segment/metadatacache/refresh/time that measures the time to call refresh(segmentsToRefresh, dataSourcesToRebuild). Emitted once per refresh per datasource.
Add metric segment/metadatacache/refresh/count that measures the number of segments passed to refresh. Emitted once per refresh per datasource.

rohangarg · 2023-06-20T09:16:58Z

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

@@ -403,6 +403,13 @@ public void start() throws InterruptedException
  @VisibleForTesting
  void refresh(final Set<SegmentId> segmentsToRefresh, final Set<String> dataSourcesToRebuild) throws IOException
  {
+    long startMillis = System.currentTimeMillis();


don't recommend using currentTimeMillis in any new code. I'd suggest using nanoTime and then converting it to the needed duration

Why do you recommend nanoTime, @rohangarg ?

since that is always monotonically increasing in a JVM's lifetime, I don't think currentTimeMillis is, since it comes from the system time.

Ah, interesting. It does seem that currentTimeMillis can sometimes run backwards!

I still feel currentTimeMillis would be a better fit here as it is a cheaper call and should be (guaranteed to be?) monotonic at least when called successively from the same thread in the absence of clock adjustments.

But either of the two approaches works for me.

I think the monotonicity depends on the NTP updates (on cloud instances), so not sure doing from same thread affects it. Also regarding cheapness, I think both calls are cheap and infrequent enough to not become a bottleneck for performance consideration. Further, the performance of each is also platform dependent I think.
I felt that for elapsed durations, probably something closer to a timer is better than using clock times.

Anyways, I'm ok with using any method.

Thanks for the feedback. nanoTime seems like the better option for measuring elapsed duration.

kfaraz

Thanks for the changes, @findingrish .

I wonder if these names would be better aligned with existing Druid metrics:

segment/metadatacache/refresh/time
segment/metadatacache/refresh/count

kfaraz · 2023-06-20T09:10:02Z

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

@@ -403,6 +403,13 @@ public void start() throws InterruptedException
  @VisibleForTesting
  void refresh(final Set<SegmentId> segmentsToRefresh, final Set<String> dataSourcesToRebuild) throws IOException
  {
+    long startMillis = System.currentTimeMillis();
+
+    emitter.emit(ServiceMetricEvent.builder().build(


It would be better to emit the dimension dataSource with this metric. So we should probably emit it from refreshSegmentsForDatasource instead.

The time metric could be per datasource too. The time duration is already being tracked and logged, we just need to emit it.

Should we report total/datasource value for both the metrics?

No, just add the dimension dataSource while emitting the metric. Aggregation is not required. It can be summed up wherever the metric is being collected.

findingrish · 2023-06-20T18:12:38Z

Thanks for the changes, @findingrish .

I wonder if these names would be better aligned with existing Druid metrics:

segment/metadatacache/refresh/time

segment/metadatacache/refresh/count

Thanks for the suggestion. What does segment represent?

Would something like broker/segmentmetadatacache/refresh/time make sense?
In general, what is the pattern of naming metrics in druid?

kfaraz · 2023-06-21T03:05:21Z

In general, what is the pattern of naming metrics in druid?

We don't really have any guidelines in place yet. But if you look at the docs, metrics typically fall into one of these buckets:

segment/ : related to segment data or metadata, something that can be tracked at the segment level
task/: task management
ingest/: ingestion stats, row counts, etc
query/: query execution
sys/, jvm/, jetty/: non-Druid system-related metrics

There are some which could have probably fit into the above, so I wouldn't advocate them. But these are:

interval/, compact/: these are all compaction metrics and could have been under ingest/
taskSlot/, worker/, compactTask/: could have been grouped into task/
tier/: probably better named as cluster/

The service name need not be a part of the metric (i.e. broker/ prefix is not required) as the service dimension is already emitted with all metrics. (The only metric with service name is coordinator/time and it is an ambiguous name at best).

I suggested segment/metadatacache/ because it relates to segment metadata, and because we already allude to SegmentMetadataCache class as metadatacache in another metric (init/metadatacache/time).

The above are my opinions to reduce complexity for a user. You can choose some other nomenclature if you can reason about it.

kfaraz

LGTM. @findingrish , please update the metrics documentation too.

Edit: Please add a couple of tests to verify the emission of this metric.

kfaraz · 2023-06-21T08:57:22Z

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

+
+    emitter.emit(builder.build("segment/metadatacache/refresh/count", segments.size()));
+
+    final long startNanos = System.nanoTime();


Nit: This should probably be the first line of the method, so that we account for all the operations here.

kfaraz · 2023-06-21T08:58:02Z

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

@@ -783,10 +789,13 @@ private Set<SegmentId> refreshSegmentsForDataSource(final String dataSource, fin
      yielder.close();
    }

+    long refreshDurationMillis = (System.nanoTime() - startNanos) / 1_000_000;


Nit: for readability

Suggested change

long refreshDurationMillis = (System.nanoTime() - startNanos) / 1_000_000;

long refreshDurationMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos);

…che-visibility

kfaraz · 2023-06-22T09:15:09Z

docs/operations/metrics.md

@@ -66,6 +66,9 @@ Metrics may have additional dimensions beyond those listed above.
 |`sqlQuery/bytes`|Number of bytes returned in the SQL query response.|`id`, `nativeQueryIds`, `dataSource`, `remoteAddress`, `success`, `engine`| |
 |`init/serverview/time`|Time taken to initialize the broker server view. Useful to detect if brokers are taking too long to start.||Depends on the number of segments.|
 |`init/metadatacache/time`|Time taken to initialize the broker segment metadata cache. Useful to detect if brokers are taking too long to start||Depends on the number of segments.|
+|`segment/metadatacache/refresh/count`|Number of segments to refresh in broker segment metadata cache.|`dataSource`|
+|`segment/metadatacache/refresh/count`|Number of segments to refresh in broker segment metadata cache.|`dataSource`|


Duplicate entry?

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

kfaraz · 2023-06-22T09:17:16Z

sql/src/test/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCacheTest.java

+  @Test
+  public void testRefreshShouldEmitMetrics() throws InterruptedException
+  {
+    ServiceEmitter mockEmitter = Mockito.mock(ServiceEmitter.class);


Use instance of StubServiceEmitter instead.

kfaraz · 2023-06-22T09:19:33Z

sql/src/test/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCacheTest.java

+    Assert.assertEquals(emittedEvents.get("segment/metadatacache/refresh/count")
+                                     .getUserDims()
+                                     .get(DruidMetrics.DATASOURCE), "some_datasource");
+    Assert.assertEquals(emittedEvents.get("segment/metadatacache/refresh/time")


Using StubServiceEmitter.getMetricValues() will simplify this code.

Instead of verifying the exact value, I am verifying that the metrics are emitted with dataSource dimension.

getMetricValues can be used for that too because it allows you to pass a set of dimension filters. See some of the other tests where it is being used.

yes, I missed this. Anyways, have updated the code.

kfaraz · 2023-06-22T13:08:38Z

sql/src/test/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCacheTest.java

+    Map<String, Set<Object>> emittedEventsMap =
+        emitter.getEvents()
+               .stream()
+               .map(ServiceMetricEvent.class::cast)
+               .collect(Collectors.groupingBy(
+                   ServiceMetricEvent::getMetric,
+                   Collectors.mapping(sme -> sme.getUserDims().get(DruidMetrics.DATASOURCE), Collectors.toSet())
+               ));
+    Assert.assertTrue(emittedEventsMap.containsKey("init/metadatacache/time"));
+    Assert.assertTrue(emittedEventsMap.get("segment/metadatacache/refresh/count").size() > 0);
+    Assert.assertTrue(emittedEventsMap.get("segment/metadatacache/refresh/time").size() > 0);


something like this:

Suggested change

Map<String, Set<Object>> emittedEventsMap =

emitter.getEvents()

.stream()

.map(ServiceMetricEvent.class::cast)

.collect(Collectors.groupingBy(

ServiceMetricEvent::getMetric,

Collectors.mapping(sme -> sme.getUserDims().get(DruidMetrics.DATASOURCE), Collectors.toSet())

));

Assert.assertTrue(emittedEventsMap.containsKey("init/metadatacache/time"));

Assert.assertTrue(emittedEventsMap.get("segment/metadatacache/refresh/count").size() > 0);

Assert.assertTrue(emittedEventsMap.get("segment/metadatacache/refresh/time").size() > 0);

emitter.verifyEmitted("init/metadatacache/time", 1);

emitter.verifyEmitted("segment/metadatacache/refresh/time", ImmutableMap.of(DruidMetrics.DATASOURCE, 'yourds', 1));

kfaraz · 2023-06-22T13:09:01Z

sql/src/test/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCacheTest.java

+  public void testRefreshShouldEmitMetrics() throws InterruptedException
+  {
+    StubServiceEmitter emitter = new StubServiceEmitter("broker", "host");
+    buildSchemaMarkAndTableLatch(SEGMENT_CACHE_CONFIG_DEFAULT, emitter);


Instead of this, can we just instantiate a SchemaMetadataCache and call refresh from this test method itself?

rohangarg · 2023-06-22T15:08:59Z

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java

@@ -707,14 +709,19 @@ private long recomputeIsRealtime(ImmutableSet<DruidServerMetadata> servers)
  private Set<SegmentId> refreshSegmentsForDataSource(final String dataSource, final Set<SegmentId> segments)
      throws IOException
  {
+    final long startTimeNanos = System.nanoTime();


Since you've given this enough thought - probably Guava's StopWatch is a good utility to use here. It is also used at a couple of more place and provides the elapsed and conversion methods as well

You can consider this change, incase you're going to make other changes to the PR too. no point in running CI for this :)

…che-visibility

New metrics: - `segment/metadatacache/refresh/time`: time taken to refresh segments per datasource - `segment/metadatacache/refresh/count`: number of segments being refreshed per datasource

Report metrics for SegmentMetadataCache refresh

75957a9

rohangarg reviewed Jun 20, 2023

View reviewed changes

kfaraz reviewed Jun 20, 2023

View reviewed changes

kfaraz added the Area - Metrics/Event Emitting label Jun 20, 2023

emit refresh time and count metric for dataSource

7bd1276

kfaraz approved these changes Jun 21, 2023

View reviewed changes

findingrish added 3 commits June 22, 2023 02:16

add test for emitted metrics

5d4b0ed

Merge remote-tracking branch 'upstream/master' into segmentmetadataca…

6ec8c35

…che-visibility

update metrics doc

9a120b1

github-actions bot added the Area - Documentation label Jun 22, 2023

findingrish added 2 commits June 22, 2023 12:09

reformat

1dfc3cd

reformat

d14aabd

kfaraz reviewed Jun 22, 2023

View reviewed changes

sql/src/main/java/org/apache/druid/sql/calcite/schema/SegmentMetadataCache.java Show resolved Hide resolved

kfaraz reviewed Jun 22, 2023

View reviewed changes

findingrish added 3 commits June 22, 2023 15:19

update docs

086bc76

use StubServiceEmitter in test

20a2ea7

remove unused import

1258140

kfaraz reviewed Jun 22, 2023

View reviewed changes

rohangarg reviewed Jun 22, 2023

View reviewed changes

findingrish added 3 commits June 23, 2023 01:19

update test

0372091

fix checkstyle

74ace26

Merge remote-tracking branch 'upstream/master' into segmentmetadataca…

4176824

…che-visibility

kfaraz merged commit 155fde3 into apache:master Jun 23, 2023

abhishekagarwal87 added this to the 27.0 milestone Jul 19, 2023

AmatyaAvadhanula mentioned this pull request Aug 6, 2023

[DRAFT] 27.0.0 release notes #14761

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve SegmentMetadataCache visibility #14453

Improve SegmentMetadataCache visibility #14453

findingrish commented Jun 20, 2023 •

edited

Loading

rohangarg Jun 20, 2023

kfaraz Jun 20, 2023

rohangarg Jun 20, 2023

kfaraz Jun 20, 2023 •

edited

Loading

rohangarg Jun 20, 2023

findingrish Jun 20, 2023

kfaraz left a comment

kfaraz Jun 20, 2023

kfaraz Jun 20, 2023

findingrish Jun 20, 2023 •

edited

Loading

kfaraz Jun 21, 2023

findingrish commented Jun 20, 2023

kfaraz commented Jun 21, 2023 •

edited

Loading

kfaraz left a comment •

edited

Loading

kfaraz Jun 21, 2023

kfaraz Jun 21, 2023

kfaraz Jun 22, 2023

findingrish Jun 22, 2023

kfaraz Jun 22, 2023

kfaraz Jun 22, 2023

findingrish Jun 22, 2023

kfaraz Jun 22, 2023

findingrish Jun 23, 2023

kfaraz Jun 22, 2023 •

edited

Loading

kfaraz Jun 22, 2023 •

edited

Loading

rohangarg Jun 22, 2023

rohangarg Jun 22, 2023


		emitter.emit(builder.build("segment/metadatacache/refresh/count", segments.size()));

		final long startNanos = System.nanoTime();

	long refreshDurationMillis = (System.nanoTime() - startNanos) / 1_000_000;
	long refreshDurationMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos);

Improve SegmentMetadataCache visibility #14453

Improve SegmentMetadataCache visibility #14453

Conversation

findingrish commented Jun 20, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kfaraz Jun 20, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kfaraz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

findingrish Jun 20, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

findingrish commented Jun 20, 2023

kfaraz commented Jun 21, 2023 • edited Loading

kfaraz left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kfaraz Jun 22, 2023 • edited Loading

Choose a reason for hiding this comment

kfaraz Jun 22, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

findingrish commented Jun 20, 2023 •

edited

Loading

kfaraz Jun 20, 2023 •

edited

Loading

findingrish Jun 20, 2023 •

edited

Loading

kfaraz commented Jun 21, 2023 •

edited

Loading

kfaraz left a comment •

edited

Loading

kfaraz Jun 22, 2023 •

edited

Loading

kfaraz Jun 22, 2023 •

edited

Loading