This message was deleted Apache Druid #troubleshooting

Join Slack

This message was deleted.

# troubleshooting

Slackbot

02/03/2023, 7:04 PM

This message was deleted.

Kai Sun

02/03/2023, 7:07 PM

The screen shot is here.

Sergio Ferragut

02/03/2023, 8:23 PM

👀

Sergio Ferragut

02/03/2023, 8:30 PM

Hi @Kai Sun, the additional log entry is a clue. It is a metric entry (I'm guessing you are using a log emitter for metrics). My initial thought is segment availability. Did you run these queries right after doing the corresponding ingestion?

Sergio Ferragut

02/03/2023, 8:36 PM

Segment availability meaning that batch ingestion runs and completes, publishes the segments to deep storage and some time later (up to a minute by default) the coordinator runs a cycle and decides which historicals should upload the segment. The historicals follow suit and load the segment, at that time they announce it to the broker which will then "see" the segment. Before that the broker does not know of the existence of the segment, so I'm guessing it doesn't see any data for the datasource and quickly ends the calculation with no data. This is just a hunch that this is what is happening, but you can confirm it by looking at the coordinator/historical logs for the segment assignment and announcement respectively.

Kai Sun

02/04/2023, 12:48 AM

@Sergio Ferragut, there is no ingestion running in this case. Here, the data is ingested from S3 couple days ago.

Kai Sun

02/04/2023, 12:54 AM

Here, in the third time when we run this, we have two log lines: 1/ line at

2023-02-03T00:32:18,723

, native time series query 2/ line at

2023-02-03T00:32:18,723

, sql of the original query. However, for the first two time, we don't have the original query log. Only the native time serious query log. And the query seems to return success as "true".

Kai Sun

02/04/2023, 12:59 AM

Other than that, the 1/ line @

2023-02-03T00:32:18,723

and line at @

2023-02-03T00:32:18,723

have exactly the same native query, except the query returning time, query id and query sql id.

Kai Sun

02/04/2023, 12:59 AM

The query time is 1ms vs 10169ms (10sec).

Kai Sun

02/04/2023, 1:00 AM

The native query time series query can't finish within 1ms, right?

Sergio Ferragut

02/04/2023, 1:01 AM

Okay, I see. It might still make sense to look at the historical logs to see if there were any announcements at that time, also are you using zookeeper for segment announcement? Has zookeeper presented any issues. I’m still following the theory that the brokers’ segment timeline was not correct at the time.

Sergio Ferragut

02/04/2023, 1:02 AM

Right on the 1ms return, unless it thinks there is no work to do.

Kai Sun

02/04/2023, 1:10 AM

I’m still following the theory that the brokers’ segment timeline was not correct at the time.|

if it is the timeline issue, would there be another log between the

2023-02-03T00:29:51,658

log line and

2023-02-03T00:32:18,723

log line? Say updating the timeline?

Sergio Ferragut

02/04/2023, 1:12 AM

I'm not sure. I'm trying to think what could cause this behavior.

Kai Sun

02/04/2023, 1:20 AM

Here is some logs from one of the historicals:

Copy code

2023-02-03T00:19:55,534 INFO [SimpleDataSegmentChangeHandler-0] org.apache.druid.segment.loading.SegmentLocalCacheManager - Deleting directory[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z/2023-01-22T01:35:36.868Z/1261]
2023-02-03T00:30:34,268 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850
2023-02-03T00:30:34,268 INFO [ZKCoordinator--2] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850]
2023-02-03T00:30:36,333 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848
2023-02-03T00:30:36,333 INFO [ZKCoordinator--4] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848]
2023-02-03T00:30:38,771 INFO [ZKCoordinator--0] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_4602
2023-02-03T00:30:38,771 INFO [ZKCoordinator--0] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602]
2023-02-03T00:30:39,130 INFO [ZKCoordinator--2] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734349253 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850]
2023-02-03T00:30:39,162 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:41:22.595Z_3f236065177048489015966fb770bd5b13]
2023-02-03T00:30:39,166 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850]
2023-02-03T00:30:39,166 INFO [ZkCoordinator] org.apache.druid.server.coordination.ZkCoordinator - zNode[/monc-ra-common-lab1/loadQueue/10.64.209.172:8088/mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850] was removed
2023-02-03T00:30:40,462 INFO [ZKCoordinator--3] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15868
2023-02-03T00:30:40,462 INFO [ZKCoordinator--3] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868]
2023-02-03T00:30:41,411 INFO [ZKCoordinator--4] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734611021 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848]
2023-02-03T00:30:41,565 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:43:45.887Z_d7403100f3824e68982a9c541d66568314]
2023-02-03T00:30:41,571 INFO [ZkCoordinator] org.apache.druid.server.coordination.ZkCoordinator - zNode[/monc-ra-common-lab1/loadQueue/10.64.209.172:8088/mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848] was removed
2023-02-03T00:30:41,571 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848]
2023-02-03T00:30:41,860 INFO [ZKCoordinator--1] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_9624
2023-02-03T00:30:41,860 INFO [ZKCoordinator--1] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/9624/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/9624]
2023-02-03T00:30:44,130 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-03T00:00:00.000Z_2022-12-04T00:00:00.000Z_2023-01-22T06:45:38.256Z_4714
2023-02-03T00:30:44,130 INFO [ZKCoordinator--2] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-03T00:00:00.000Z_2022-12-04T00:00:00.000Z/2023-01-22T06:45:38.256Z/4714/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-03T00:00:00.000Z_2022-12-04T00:00:00.000Z/2023-01-22T06:45:38.256Z/4714]
2023-02-03T00:30:46,453 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z_2023-01-22T01:35:36.868Z_1153
2023-02-03T00:30:46,453 INFO [ZKCoordinator--4] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z/2023-01-22T01:35:36.868Z/1153/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z/2023-01-22T01:35:36.868Z/1153]
2023-02-03T00:30:47,119 INFO [ZKCoordinator--0] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734792578 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602]
2023-02-03T00:30:47,384 INFO [ZKCoordinator--0] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_4602] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:46:02.230Z_9cc829a4916c4770ac98a7440774994515]
2023-02-03T00:30:47,390 INFO [ZKCoordinator--0] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_4602]
2023-02-03T00:30:47,390 INFO [ZkCoordinator] org.apache.druid.server.coordination.ZkCoordinator - zNode[/monc-ra-common-lab1/loadQueue/10.64.209.172:8088/mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_4602] was removed
2023-02-03T00:30:50,070 INFO [ZKCoordinator--3] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734368894 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868]
2023-02-03T00:30:50,278 INFO [ZKCoordinator--3] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15868] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:46:02.230Z_9cc829a4916c4770ac98a7440774994515]
2023-02-03T00:30:50,283 INFO [ZKCoordinator--3] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15868]
2023-02-03T00:30:50,283 INFO [ZkCoordinator] org.apache.druid.server.coordination.ZkCoordinator - zNode[/monc-ra-common-lab1/loadQueue/10.64.209.172:8088/mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15868] was removed

Sergio Ferragut

02/04/2023, 1:25 AM

What are the retention rules on this data source?

Kai Sun

02/04/2023, 1:25 AM

For the 10s one, I did see something like this in historical.

Kai Sun

02/04/2023, 1:27 AM

Copy code

2023-02-03T00:30:54,779 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z_2023-01-22T01:35:36.868Z_1153]
2023-02-03T00:32:15,881 INFO [qtp2085313771-165] org.apache.druid.server.log.LoggingRequestLogger - 2023-02-03T00:32:09.255Z    10.64.210.54    {"queryType":"timeseries","dataSource":{"type":"table","name":"mulesoft_long_query_d1_2"},"intervals":{"type":"segments","segments":[{"itvl":"2022-12-01T00:00:00.000Z/2022-12-02T00:00:00.000Z","ver":"2023-01-21T04:57:45.488Z","part":253},{"itvl":"2022-12-01T00:00:00.000Z/2022-12-02T00:00:00.000Z","ver":"2023-01-21T04:57:45.488Z","part":268},{"itvl":"2022-12-01T00:00:00.000Z/2022-12-02T00:00:00.000Z","ver":"2023-01-21T04:57:45.488Z","part":343},{"itvl":"2022-12-01T00:00:00.000Z/2022-12-02T00:00:00.000Z","ver":"2023-01-21T04:57:45.488Z","part":483},
...
:00.000Z","ver":"2023-01-24T05:05:28.527Z","part":16599},{"itvl":"2022-12-07T00:00:00.000Z/2022-12-08T00:00:00.000Z","ver":"2023-01-24T05:05:28.527Z","part":16742},{"itvl":"2022-12-07T00:00:00.000Z/2022-12-08T00:00:00.000Z","ver":"2023-01-24T05:05:28.527Z","part":16806},{"itvl":"2022-12-08T00:00:00.000Z/2022-12-09T00:00:00.000Z","ver":"2023-01-24T08:48:52.213Z","part":111},{"itvl":"2022-12-08T00:00:00.000Z/2022-12-09T00:00:00.000Z","ver":"2023-01-24T08:48:52.213Z","part":209},{"itvl":"2022-12-08T00:00:00.000Z/2022-12-09T00:00:00.000Z","ver":"2023-01-24T08:48:52.213Z","part":326}]},"descending":false,"virtualColumns":[],"filter":null,"granularity":{"type":"all"},"aggregations":[{"type":"quantilesDoublesSketch","name":"a0:agg","fieldName":"duration","k":128,"maxStreamLength":1000000000}],"postAggregations":[],"limit":2147483647,"context":{"bySegment":true,"defaultTimeout":3600000,"finalize":false,"grandTotal":false,"maxQueuedBytes":264791,"maxScatterGatherBytes":9223372036854775807,"populateCache":false,"priority":0,"queryFailTime":1675387928554,"queryId":"933c637c-32b2-462e-ad33-e240af395772","sqlOuterLimit":101,"sqlQueryId":"f8bdbcd8-9f52-4af9-b51b-7cdc52c71cb2","timeout":3599300}}    {"query/time":6623,"query/bytes":5258965,"success":true,"identity":"allowAll"}

Kai Sun

02/04/2023, 1:28 AM

Basically for sqlQueryId f8bdbcd8-9f52-4af9-b51b-7cdc52c71cb2, the historical executed the query

Sergio Ferragut

02/04/2023, 1:30 AM

From your first historical log, I see that there were segments being downloaded and announced between the time of the first two query attempts and the successful one. So it could be related. How many segments does this datasource have? What are the retention rules on it, I see at the top of the historical that a segment for 2022-12-02/2022-12-03 was dropped. this isn't necessarily an issue, just trying to understand the whole picture.

Kai Sun

02/04/2023, 1:33 AM

From your first historical log, I see that there were segments being downloaded and announced between the time of the first two query attempts and the successful one.

Interesting. are you saying this is logs that historical is downloading the segments?

Copy code

2023-02-03T00:19:55,200 INFO [SimpleDataSegmentChangeHandler-3] org.apache.druid.segment.loading.SegmentLocalCacheManager - Deleting directory[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-03T00:00:00.000Z_2022-12-04T00:00:00.000Z/2023-01-22T06:45:38.256Z/3787]
2023-02-03T00:19:55,533 INFO [SimpleDataSegmentChangeHandler-0] org.apache.druid.server.SegmentManager - Attempting to close segment mulesoft_long_query_d1_2_2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z_2023-01-22T01:35:36.868Z_1261
2023-02-03T00:19:55,534 INFO [SimpleDataSegmentChangeHandler-0] org.apache.druid.segment.loading.SegmentLocalCacheManager - Deleting directory[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-02T00:00:00.000Z_2022-12-03T00:00:00.000Z/2023-01-22T01:35:36.868Z/1261]


2023-02-03T00:30:34,268 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850
2023-02-03T00:30:34,268 INFO [ZKCoordinator--2] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850]
2023-02-03T00:30:36,333 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848
2023-02-03T00:30:36,333 INFO [ZKCoordinator--4] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848]
2023-02-03T00:30:38,771 INFO [ZKCoordinator--0] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_4602
2023-02-03T00:30:38,771 INFO [ZKCoordinator--0] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z/2023-01-22T19:35:12.273Z/4602]
2023-02-03T00:30:39,130 INFO [ZKCoordinator--2] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734349253 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z/2023-01-24T05:05:28.527Z/7850]
2023-02-03T00:30:39,162 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:41:22.595Z_3f236065177048489015966fb770bd5b13]
2023-02-03T00:30:39,166 INFO [ZKCoordinator--2] org.apache.druid.server.coordination.ZkCoordinator - Completed request [LOAD: mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850]
2023-02-03T00:30:39,166 INFO [ZkCoordinator] org.apache.druid.server.coordination.ZkCoordinator - zNode[/monc-ra-common-lab1/loadQueue/10.64.209.172:8088/mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850] was removed
2023-02-03T00:30:40,462 INFO [ZKCoordinator--3] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15868
2023-02-03T00:30:40,462 INFO [ZKCoordinator--3] org.apache.druid.storage.s3.S3DataSegmentPuller - Pulling index at path[CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868/index.zip'}] to outDir[/var/druid/segments/mulesoft_long_query_d1_2/2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z/2023-01-22T06:45:49.365Z/15868]
2023-02-03T00:30:41,411 INFO [ZKCoordinator--4] org.apache.druid.storage.s3.S3DataSegmentPuller - Loaded 734611021 bytes from [CloudObjectLocation{bucket='monc-ra-common-lab1-monitoring-dev1-uswest2-s3', path='druid_moncloud_events/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848/index.zip'}] to [/var/druid/segments/mulesoft_long_query_d1_2/2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z/2023-01-22T19:35:15.169Z/4848]
2023-02-03T00:30:41,565 INFO [ZKCoordinator--4] org.apache.druid.server.coordination.BatchDataSegmentAnnouncer - Announcing segment[mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_4848] at existing path[/monc-ra-common-lab1/segments/10.64.209.172:8088/10.64.209.172:8088_historical__default_tier_2023-01-31T07:43:45.887Z_d7403100f3824e68982a9c541d66568314]

Sergio Ferragut

02/04/2023, 1:34 AM

yes, and you can see the segments being announced

Announcing segment[mulesoft_long_query_d1_2_2022-12-07T00:00:00.000Z_2022-12-08T00:00:00.000Z_2023-01-24T05:05:28.527Z_7850]

Sergio Ferragut

02/04/2023, 1:36 AM

that's when the broker finds out about them. The question is whether the broker knew about these segments in another historical or not and maybe these are just being balanced among historicals. This is why I want to understand your retention rules and whether they have changed, to see why the historical is dropping and loading these segments.

Kai Sun

02/04/2023, 1:38 AM

There is only one copy (1 replica) per segment to say some space in this case.

Kai Sun

02/04/2023, 1:39 AM

This data source has 75496 segments

Kai Sun

02/04/2023, 1:39 AM

Retention for ever

Sergio Ferragut

02/04/2023, 1:40 AM

hmmm... interesting. In theory the coordinator should not drop a segment from a historical until it has been loaded in another if

replicants=1

, so there could be a problem in the segment movement logic when doing rebalancing in this scenario.

Sergio Ferragut

02/04/2023, 1:41 AM

What version of Druid are you on?

Sergio Ferragut

02/04/2023, 1:42 AM

Do you see any problems with zookeeper at that time? anything in the zookeeper logs?

Kai Sun

02/04/2023, 1:44 AM

0.23 version of druid

Sergio Ferragut

02/04/2023, 1:48 AM

Now with 75k segments, there should have been at least some in the timeline even if these few were not. The timing of the announcements is curious, but it should not control the overall query result event if it was missing a few segments (which should not occur).

Kai Sun

02/04/2023, 1:52 AM

Do you see any problems with zookeeper at that time? anything in the zookeeper logs?

Checked one. Nothing special.

Copy code

2023-02-03 00:27:58,819 [myid:1] - INFO  [NIOWorkerThread-22:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:60772
2023-02-03 00:28:13,806 [myid:1] - INFO  [NIOWorkerThread-23:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:41416
2023-02-03 00:28:13,808 [myid:1] - INFO  [NIOWorkerThread-24:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:41428
2023-02-03 00:28:28,817 [myid:1] - INFO  [NIOWorkerThread-25:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:47710
2023-02-03 00:28:28,819 [myid:1] - INFO  [NIOWorkerThread-26:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:47722
2023-02-03 00:28:43,813 [myid:1] - INFO  [NIOWorkerThread-27:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:50748
2023-02-03 00:28:43,815 [myid:1] - INFO  [NIOWorkerThread-28:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:50756
2023-02-03 00:28:58,817 [myid:1] - INFO  [NIOWorkerThread-29:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57880
2023-02-03 00:28:58,819 [myid:1] - INFO  [NIOWorkerThread-30:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57884
2023-02-03 00:29:13,805 [myid:1] - INFO  [NIOWorkerThread-31:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:54940
2023-02-03 00:29:13,807 [myid:1] - INFO  [NIOWorkerThread-32:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:54942
2023-02-03 00:29:28,802 [myid:1] - INFO  [NIOWorkerThread-33:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:35482
2023-02-03 00:29:28,803 [myid:1] - INFO  [NIOWorkerThread-34:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:35492
2023-02-03 00:29:43,813 [myid:1] - INFO  [NIOWorkerThread-35:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:33280
2023-02-03 00:29:43,815 [myid:1] - INFO  [NIOWorkerThread-36:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:33286
2023-02-03 00:29:58,814 [myid:1] - INFO  [NIOWorkerThread-37:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:51132
2023-02-03 00:29:58,815 [myid:1] - INFO  [NIOWorkerThread-38:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:51146
2023-02-03 00:30:13,802 [myid:1] - INFO  [NIOWorkerThread-39:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:39664
2023-02-03 00:30:13,804 [myid:1] - INFO  [NIOWorkerThread-40:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:39676
2023-02-03 00:30:28,797 [myid:1] - INFO  [NIOWorkerThread-41:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:36768
2023-02-03 00:30:28,799 [myid:1] - INFO  [NIOWorkerThread-42:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:36776
2023-02-03 00:30:43,814 [myid:1] - INFO  [NIOWorkerThread-43:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:37576
2023-02-03 00:30:43,816 [myid:1] - INFO  [NIOWorkerThread-44:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:37588
2023-02-03 00:30:58,826 [myid:1] - INFO  [NIOWorkerThread-45:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57450
2023-02-03 00:30:58,829 [myid:1] - INFO  [NIOWorkerThread-46:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57460
2023-02-03 00:31:13,798 [myid:1] - INFO  [NIOWorkerThread-47:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:48886
2023-02-03 00:31:13,800 [myid:1] - INFO  [NIOWorkerThread-48:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:48890
2023-02-03 00:31:28,801 [myid:1] - INFO  [NIOWorkerThread-49:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:40132
2023-02-03 00:31:28,803 [myid:1] - INFO  [NIOWorkerThread-50:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:40138
2023-02-03 00:31:43,793 [myid:1] - INFO  [NIOWorkerThread-51:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:58168
2023-02-03 00:31:43,794 [myid:1] - INFO  [NIOWorkerThread-52:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:58178
2023-02-03 00:31:58,805 [myid:1] - INFO  [NIOWorkerThread-53:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:46844
2023-02-03 00:31:58,807 [myid:1] - INFO  [NIOWorkerThread-54:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:46850
2023-02-03 00:32:13,829 [myid:1] - INFO  [NIOWorkerThread-55:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:53562
2023-02-03 00:32:13,831 [myid:1] - INFO  [NIOWorkerThread-56:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:53572
2023-02-03 00:32:28,798 [myid:1] - INFO  [NIOWorkerThread-57:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57650
2023-02-03 00:32:28,800 [myid:1] - INFO  [NIOWorkerThread-58:NIOServerCnxn@535] - Processing mntr command from /10.64.213.206:57656

Kai Sun

02/04/2023, 1:52 AM

Do I need to check the leader at the time?

Sergio Ferragut

02/04/2023, 1:52 AM

perhaps it will be good to take a look at the coordinator log at the time,

Sergio Ferragut

02/04/2023, 1:53 AM

On the zookeeper side, just looking to see if there are errors.

Kai Sun

02/04/2023, 2:00 AM

here is the one log from coordinator (we have 3, but this one may be just the leader)

Kai Sun

02/04/2023, 2:01 AM

Copy code

2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.192.239:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,673,252,587 bytes queued, 557,003,401,132 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.207.176:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,272,192 bytes queued, 557,006,367,510 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.192.187:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,322,869 bytes queued, 557,008,437,379 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.205.155:8088, historical, _default_tier] has 3 left to load, 0 left to drop, 2,203,786,150 bytes queued, 557,310,966,003 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.211.120:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,030,689 bytes queued, 557,336,684,990 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.206.250:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,673,638,326 bytes queued, 557,401,274,125 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.208.11:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,146,765 bytes queued, 557,460,897,371 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.213.132:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,217,136 bytes queued, 557,649,186,940 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.202.208:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,937,494,324 bytes queued, 557,723,735,958 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.206.138:8088, historical, _default_tier] has 1 left to load, 0 left to drop, 734,886,727 bytes queued, 557,741,219,853 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.210.5:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,867,630 bytes queued, 558,207,424,265 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.193.152:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,672,785,551 bytes queued, 558,232,313,128 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.198.104:8088, historical, _default_tier] has 2 left to load, 0 left to drop, 1,468,978,641 bytes queued, 558,844,888,224 bytes served.
2023-02-03T00:31:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:31:20,343 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:31:29,832 INFO [org.apache.druid.metadata.SqlSegmentsMetadataManager-Exec--0] org.apache.druid.metadata.SqlSegmentsMetadataManager - Polled and found 76,962 segments in the database
2023-02-03T00:32:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:32:08,285 INFO [LookupCoordinatorManager--1] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists
2023-02-03T00:32:20,347 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:32:32,316 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.LogUsedSegments - Found [76,962] used segments.
2023-02-03T00:32:32,396 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.
2023-02-03T00:32:32,446 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Dropping segment [mulesoft_long_query_d1_2_2022-12-06T00:00:00.000Z_2022-12-07T00:00:00.000Z_2023-01-22T19:35:15.169Z_266] on server [10.64.200.209:8088] in tier [_default_tier]
2023-02-03T00:32:32,478 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Dropping segment [mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_15384] on server [10.64.206.185:8088] in tier [_default_tier]
2023-02-03T00:32:32,483 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Dropping segment [mulesoft_long_query_d1_2_2022-12-04T00:00:00.000Z_2022-12-05T00:00:00.000Z_2023-01-22T06:45:49.365Z_13077] on server [10.64.198.104:8088] in tier [_default_tier]
2023-02-03T00:33:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:33:20,350 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:33:58,328 INFO [BatchServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - New Server[DruidServerMetadata{name='10.64.209.71:8088', hostAndPort='10.64.209.71:8088', hostAndTlsPort='null', maxSize=3000000000000, tier='_default_tier', type=historical, priority=0}]
2023-02-03T00:33:58,342 INFO [NodeRoleWatcher[HISTORICAL]] org.apache.druid.discovery.BaseNodeRoleWatcher - Node[<http://10.64.209.71:8088>] of role[historical] detected.
2023-02-03T00:34:06,439 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:34:08,285 INFO [LookupCoordinatorManager--1] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists
2023-02-03T00:34:20,354 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:34:42,109 INFO [org.apache.druid.metadata.SqlSegmentsMetadataManager-Exec--0] org.apache.druid.metadata.SqlSegmentsMetadataManager - Polled and found 76,962 segments in the database
2023-02-03T00:35:06,439 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:35:19,211 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Found 99 active servers, 0 decommissioning servers
2023-02-03T00:35:19,211 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 4 segments for moving from decommissioning servers

Kai Sun

02/04/2023, 2:02 AM

And this is the upper part

Kai Sun

02/04/2023, 2:02 AM

Copy code

2023-02-03T00:30:48,911 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Loading in progress, skipping drop until loading is complete
2023-02-03T00:30:48,932 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Assigning 'primary' for segment [perf_data_1T_1_2021-06-26T00:00:00.000Z_2021-06-27T00:00:00.000Z_2022-10-14T21:13:21.062Z_48] to server [10.64.209.205:8088] in tier [_default_tier]
2023-02-03T00:30:48,932 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Skipping replica assignment for tier [_default_tier]
2023-02-03T00:30:48,932 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Loading in progress, skipping drop until loading is complete
2023-02-03T00:30:48,952 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Assigning 'primary' for segment [perf_data_1T_1_2021-06-25T00:00:00.000Z_2021-06-26T00:00:00.000Z_2022-10-14T20:57:25.459Z_137] to server [10.64.209.205:8088] in tier [_default_tier]
2023-02-03T00:30:48,952 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Skipping replica assignment for tier [_default_tier]
2023-02-03T00:30:48,952 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Loading in progress, skipping drop until loading is complete
2023-02-03T00:30:48,972 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Assigning 'primary' for segment [perf_data_1T_1_2021-06-25T00:00:00.000Z_2021-06-26T00:00:00.000Z_2022-10-14T20:57:25.459Z_46] to server [10.64.214.119:8088] in tier [_default_tier]
2023-02-03T00:30:48,972 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Skipping replica assignment for tier [_default_tier]
2023-02-03T00:30:48,972 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Loading in progress, skipping drop until loading is complete
2023-02-03T00:30:48,992 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Assigning 'primary' for segment [perf_data_1T_1_2021-06-24T00:00:00.000Z_2021-06-25T00:00:00.000Z_2022-10-14T20:55:19.376Z_6] to server [10.64.202.38:8088] in tier [_default_tier]
2023-02-03T00:30:48,992 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Skipping replica assignment for tier [_default_tier]
2023-02-03T00:30:48,992 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Loading in progress, skipping drop until loading is complete
2023-02-03T00:30:49,394 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Found 99 active servers, 0 decommissioning servers
2023-02-03T00:30:49,394 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 4 segments for moving from decommissioning servers
2023-02-03T00:30:49,394 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 5 segments for balancing between active servers
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - [_default_tier]: Segments Moved: [2] Segments Let Alone: [3]
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Assigned 770 segments among 99 servers
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Dropped 3 segments among 99 servers
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Moved 2 segment(s)
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Let alone 3 segment(s)
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Load Queues:
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.214.119:8088, historical, _default_tier] has 13 left to load, 0 left to drop, 6,877,872,774 bytes queued, 551,225,185,228 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.196.234:8088, historical, _default_tier] has 3 left to load, 0 left to drop, 2,204,273,595 bytes queued, 551,875,385,133 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.194.123:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,945,525 bytes queued, 552,730,090,858 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.199.252:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,211,837 bytes queued, 553,405,618,861 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.215.19:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,139,873 bytes queued, 553,477,273,072 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.214.171:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,672,905,695 bytes queued, 553,635,926,738 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.203.70:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,673,683,656 bytes queued, 553,659,228,273 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.193.225:8088, historical, _default_tier] has 2 left to load, 0 left to drop, 1,469,533,475 bytes queued, 553,739,109,773 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.210.177:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,077,792 bytes queued, 553,782,792,312 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.199.42:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,673,374,593 bytes queued, 553,812,596,074 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.203.116:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,938,232,806 bytes queued, 553,855,809,213 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.193.43:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,672,487,585 bytes queued, 553,920,226,848 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.204.62:8088, historical, _default_tier] has 3 left to load, 0 left to drop, 2,203,697,722 bytes queued, 554,009,145,706 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.199.130:8088, historical, _default_tier] has 4 left to load, 0 left to drop, 2,937,603,762 bytes queued, 554,108,353,249 bytes served.
2023-02-03T00:30:49,597 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.208.14:8088, historical, _default_tier] has 6 left to load, 0 left to drop, 4,407,635,328 bytes queued, 554,135,971,677 bytes served.

Kai Sun

02/04/2023, 2:04 AM

Note,

Copy code

2023-02-03T00:30:49,394 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Found 99 active servers, 0 decommissioning servers
2023-02-03T00:30:49,394 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 4 segments for moving from decommissioning servers

In fact, we configured 100 historicals. It find 99 active servers. Maybe one historical is evicted from k8 due to node draining

Sergio Ferragut

02/04/2023, 2:10 AM

If you have the possibility of losing historicals frequently,

replicants=1

does represent a problem. It would not explain this, but you would momentarily lose data while another historical picks up the segments that the lost historical had. I still can't make sense of it. But one thing you might want to try is changing from zookeeper based segment announcement

druid.serverview.type=batch

druid.serverview.type=http

to communicate segment announcements without using zookeeper, that's the new default as of 25.0

Sergio Ferragut

02/04/2023, 2:11 AM

is this behavior something you can see often?

Kai Sun

02/04/2023, 2:12 AM

Current config is for load testing. I intentionally config replicant=1 to save disk space and only cluster restarting time. I did see this several times before.

Kai Sun

02/04/2023, 2:13 AM

@Sergio Ferragut, can you explain a little bit more about what is zk based segment announcement and why you think this still does not make sense?

Sergio Ferragut

02/04/2023, 2:16 AM

I mean that if the datasource has 75k segments, even if the coordinator is doing something wrong and removing some of the segments before loading them elsewhere, it does not explain your result in the first 2 query runs because the broker would've still known about the other segments. So I'm thinking it is not a coordinator/retention rule issue but something else.

Sergio Ferragut

02/04/2023, 2:17 AM

Since zk if the means of communication between the processes, and I know druid is moving away from zk, I thought you might want to see if that changes anything, but I don't have any solid theory here as to why it is happening.

Sergio Ferragut

02/04/2023, 2:18 AM

if you try

druid.serverview.type=http

it might change the behavior and at least we'll know that it is related.

Kai Sun

02/04/2023, 2:19 AM

What is the con of using http? Or put it this way, with http mode, do we still need zookeeper? And what discovery is based on zookeeper?

Kai Sun

02/04/2023, 2:20 AM

Back to the log, I do this this:

Copy code

2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.193.152:8088, historical, _default_tier] has 5 left to load, 0 left to drop, 3,672,785,551 bytes queued, 558,232,313,128 bytes served.
2023-02-03T00:30:49,598 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.198.104:8088, historical, _default_tier] has 2 left to load, 0 left to drop, 1,468,978,641 bytes queued, 558,844,888,224 bytes served.
2023-02-03T00:31:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:31:20,343 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:31:29,832 INFO [org.apache.druid.metadata.SqlSegmentsMetadataManager-Exec--0] org.apache.druid.metadata.SqlSegmentsMetadataManager - Polled and found 76,962 segments in the database
2023-02-03T00:32:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:32:08,285 INFO [LookupCoordinatorManager--1] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists
2023-02-03T00:32:20,347 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:32:32,316 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.LogUsedSegments - Found [76,962] used segments.
2023-02-03T00:32:32,396 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.

Kai Sun

02/04/2023, 2:23 AM

And the 3rd query do executed at 02-03T00:32-08, roughly at the end of this shuffling of data segments.

Sergio Ferragut

02/04/2023, 2:27 AM

zookeeper is used for multiple things: leader election, segment announcements, load/drop commands to historicals, task control and monitoring many of these functions can be changed with:

Copy code

druid.serverview.type:http                   #segment discovery
druid.coordinator.loadqueuepeon.type: "http" # load/unload commands for historicals
druid.indexer.runner.type: "httpRemote"      # task control

leader election is still on zookeeper unless you use the k8s extension for that, but that is still considered experimental.

Kai Sun

02/04/2023, 2:29 AM

Moving away from ZK seems to be the direction for Druid. Do we know what is driving this change? Is it for issues similar like this?

Sergio Ferragut

02/04/2023, 2:36 AM

I don't have the whole story, but the http based interprocess communication has been deemed a better approach: https://github.com/apache/druid/pull/13092

Sergio Ferragut

02/04/2023, 2:43 AM

You could also turn debug level logging on in the broker and see if we can get more detail when this happens again.

Kai Sun

02/04/2023, 2:50 AM

Copy code

2023-02-03T00:27:40,104 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.LogUsedSegments - Found [76,962] used segments.
2023-02-03T00:27:40,182 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.
2023-02-03T00:27:40,239 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.rules.LoadRule - Dropping segment [mulesoft_long_query_d1_2_2022-12-05T00:00:00.000Z_2022-12-06T00:00:00.000Z_2023-01-22T19:35:12.273Z_7811] on server [10.64.199.42:8088] in tier [_default_tier]
2023-02-03T00:28:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:28:08,284 INFO [LookupCoordinatorManager--1] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists
2023-02-03T00:28:17,664 INFO [org.apache.druid.metadata.SqlSegmentsMetadataManager-Exec--0] org.apache.druid.metadata.SqlSegmentsMetadataManager - Polled and found 76,962 segments in the database
2023-02-03T00:28:20,332 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:28:48,834 INFO [NodeRoleWatcher[HISTORICAL]] org.apache.druid.discovery.BaseNodeRoleWatcher - Node[<http://10.64.210.112:8088>] of role[historical] went offline.
2023-02-03T00:28:48,853 INFO [BatchServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - Server Disappeared[DruidServerMetadata{name='10.64.210.112:8088', hostAndPort='10.64.210.112:8088', hostAndTlsPort='null', maxSize=3000000000000, tier='_default_tier', type=historical, priority=0}]
2023-02-03T00:29:06,439 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:29:20,336 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:30:06,438 INFO [TaskQueue-StorageSync] org.apache.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2023-02-03T00:30:08,285 INFO [LookupCoordinatorManager--1] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists
2023-02-03T00:30:20,340 INFO [DatabaseRuleManager-Exec--0] org.apache.druid.metadata.SQLMetadataRuleManager - Polled and found 1 rule(s) for 2 datasource(s)
2023-02-03T00:30:31,804 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Found 100 active servers, 0 decommissioning servers
2023-02-03T00:30:31,804 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 4 segments for moving from decommissioning servers
2023-02-03T00:30:31,804 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - Processing 5 segments for balancing between active servers
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.BalanceSegments - [_default_tier]: Segments Moved: [1] Segments Let Alone: [4]
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Assigned 0 segments among 100 servers
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Dropped 1 segments among 100 servers
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Moved 1 segment(s)
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - [_default_tier] : Let alone 4 segment(s)
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Load Queues:
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.214.119:8088, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 551,225,185,228 bytes served.
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.196.234:8088, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 551,875,385,133 bytes served.
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.194.123:8088, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 552,730,090,858 bytes served.
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.199.252:8088, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 553,405,618,861 bytes served.
2023-02-03T00:30:32,000 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.duty.EmitClusterStatsAndMetrics - Server[10.64.215.19:8088, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 553,477,27

Kai Sun

02/04/2023, 2:51 AM

From coordinator log, there is a historical going down (from Zookeeper point of view). The timing correlates to failed query

Copy code

2023-02-03T00:28:48,853 INFO [BatchServerInventoryView-0] org.apache.druid.client.BatchServerInventoryView - Server Disappeared[DruidServerMetadata{name='10.64.210.112:8088', hostAndPort='10.64.210.112:8088', hostAndTlsPort='null', maxSize=3000000000000, tier='_default_tier', type=historical, priority=0}]

Kai Sun

02/04/2023, 2:51 AM

I will try enable debug log and kill a historical pod to see if we can replicate this issue later.

Kai Sun

02/04/2023, 2:52 AM

Thanks @Sergio Ferragut

Sergio Ferragut

02/04/2023, 2:56 AM

So, new theory, the historical went down, the broker could not talk to it and couldn’t find anywhere to get those segments, ideally it should return an error if that was the case. Anyway, a bit later the coordinator recognizes this and loads the missing segments into another historical, the broker now finds all it needs and runs.

Sergio Ferragut

02/04/2023, 2:58 AM

I think the Debug log in the broker would help see more.

Kai Sun

02/04/2023, 2:59 AM

Yes, timing wise, 1 historical down, query 1st, query 2nd and co-cordiantor reshuffle at the same time (1 replicant means some segment were not presented for sure), and finally the 3rd worked.

Kai Sun

02/04/2023, 2:59 AM

However, the 1st and 2nd results are mysterious. They should not return success with not meaningful result.

Kai Sun

02/04/2023, 3:00 AM

I would be more concerning if we have multiple replicas and this still happens.

Sergio Ferragut

02/04/2023, 3:01 AM

Agreed, I think a bug report on replicants =1 and query “success” when segments are missing would be good. Would you add that in the GitHub issues?

Kai Sun

02/04/2023, 3:02 AM

I can do that. Just in case, can you let me know the github address to make sure I enter to the right one.