https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# troubleshooting
s
This message was deleted.
s
You can control it. Take a look at parameter 
replicationThrottleLimit
in the coordinator's dynamic configuration.
k
That’s the parameter I’m playing with right now. It’s been set to 10 and I’ve increased it to 500 and it looks like it made some difference, but throttling is still happening. The symptom we are experiencing is that segments are being created and querying them return proper metadata, but data queries return no data for data ranges in question. Does that sound like a reasonable cause and effect combination?
v
what is the number of segments to load on the historicals when the throttling happens?
k
929 segments, as far as I can see:
Copy code
2023-01-06T22:02:38,785 INFO [task-runner-0-priority-0] org.apache.druid.indexing.common.task.batch.parallel.ParallelIndexSupervisorTask - Published [929] segments
2023-01-06T22:02:38,787 INFO [task-runner-0-priority-0] org.apache.druid.indexing.worker.executor.ExecutorLifecycle - Task completed with status: {
  "id" : "index_parallel_media_events.v1.media_embed_location.monthly.v1_mndemcao_2023-01-06T21:17:46.766Z",
  "status" : "SUCCESS",
  "duration" : 2687646,
  "errorMsg" : null,
  "location" : {
    "host" : null,
    "port" : -1,
    "tlsPort" : -1
  }
}
v
can you check the services tab and see the load queue in the historicals?
k
Yep, it’s empty.
I can see segment metadata and I can also see them under the 
Segments
tab.
But if I issue a query against the data in that time range, I’m getting 
Query returned no data
.
I’m getting 
20,880 results in 1.62s
for
Copy code
{
  "queryType": "segmentMetadata",
  "dataSource": "events.my_event_datasource",
  "intervals": [
    "2022-10-01/2022-11-01"
  ]
}
(that’s the time range in question)
v
How much available disk space you have on the historicals?
k
About 1.5TB available.
a
Could you please try 
select num_replicas, count(*) from sys.segments where datasource=<datasource> and "start"=<intervalStart> and "end"=<intervalEnd> group by 1
in the druid console? It's possible a few (core) segments are still unavailable
v
Hmmm…my thinking is that if the source shows as 100% available in the console then the query should not be returning empty results irrespective of throttling etc
How many historicals do you have and is this source 100% available when the query returns empty results?
And what is the query that returns empty results?
k
Yes, the datasource shows it’s 100% available and all historical nodes under the services tab have nothing to load. We have 14 historical nodes. The query is a simple Druid SQL, along the lines of:
Copy code
select sum(metric1), sum(metric2) from "datasource" where __time >= <daterange_start> and __time < <daterage_end>
I know it contains non-empty results since we have the same data in a different datasource (with different segment and query granularity) After re-running the same batch ingestion spec several times, the query above returns data that matches what we have in the original datasource. So yeah, the ultimate question here is why would re-running the same task several times produce different results.
If it’s of any help, we’re on 
0.21.0
release.
@Amatya Avadhanula the output is 2 (num replicas) and 929 (count).
s
Have the load rules changes for the new datasource recently? maybe between runs of the job? Just a thought. Could the prior ingestion have marked segments as unused due to load rules? If this were the case, you can fix this. @Saydul Bashar and I recently posted a blog on how to resolve it: https://saydul.substack.com/p/apache-druid-recovering-dropped-segments
k
@Sergio Ferragut we haven’t changed our load rules from their defaults (
loadForever
). So I imagine that’s not the problem.
Plus, if it was the case, wouldn’t it mean that segment metadata queries and 
Segments
tab would reflect that?
s
I'm not sure, and like you said, it sounds like you should not have that issue. And yes, the segments view should reflect that. Do you see all the segments as "Used" in the segments tab? 100% available means that all the segments in a Used state are loaded into one or more historicals. So I wondered about the Used status as a possible cause for the "missing" data.
k
Yeah, every segment in that datasource for this date range is available and published. And nothing clearly odd in the logs.
I imagine without more detailed info it might be difficult to debug this issue, so maybe you folks have at least some general recommendation / suspicions about what might (with emphasis on might 🙂 ) be happening here and where to look for next?
On our end, we’ve been thinking about upgrading to the latest version (as I mentioned, we’re on 
0.21.0
) right now.
Here’s an example of what I see in the 
Segments
tab.
s
Brokers also keep a map of the segments in memory in order to scatter query requests to historicals. Are there any warnings or errors in the Broker log?
k
Nothing obvious (like exceptions or warnings), AFAICS.
Correct me if I’m wrong, but if broker’s balancing type is left untouched, it should be set to 
random
and, thus, queries should be routed to random historical nodes. So if the data is loaded (and it looks like it is - with replication factor of 2), at least one of those historicals should respond with some data. I wonder if I should try querying historicals directly to see if the problem is at the “upper” layer.
s
That's a good idea. Just to clarify, the random selection of historical for a given segment query processing request, is among the ones that have the corresponding segment already available, so that should not be the root cause of this. ... unless the segment map were somehow outdated on the broker.
k
Oh, got it. Thanks!
So I pinged 
POST /druid/v2/candidates/
with the query in question and got back a bunch of segments back with IP addresses of historicals.
Based on this API reference.
OK, so I ran some queries against historicals direclty and I’m getting 0s for every date range in that data source. Query:
Copy code
{
  "queryType": "timeseries",
  "dataSource": {
    "type": "table",
    "name": "my_datasource"
  },
  "intervals": {
    "type": "intervals",
    "intervals": [
      "2022-06-01T05:00:00.000Z/2023-01-01T05:00:00.000Z"
    ]
  },
  "descending": false,
  "virtualColumns": [],
  "filter": {
    "type": "selector",
    "dimension": "dim1",
    "value": null,
    "extractionFn": null
  },
  "granularity": {
    "type": "all"
  },
  "aggregations": [
    {
      "type": "longSum",
      "name": "a0",
      "fieldName": "f1",
      "expression": null
    },
    {
      "type": "longSum",
      "name": "a1",
      "fieldName": "f2",
      "expression": null
    },
    {
      "type": "longSum",
      "name": "a2",
      "fieldName": "f3",
      "expression": null
    }
  ],
  "postAggregations": [],
  "limit": 2147483647
}
Not sure if I’m doing it correctly though - I 
POST
against 
<historical_host_ip>:8083/druid/v2?pretty
. I do get values back for the original datasource (from which I ingest data) using this method, like so:
Copy code
[ {
  "timestamp" : "2022-12-14T05:00:00.000Z",
  "result" : {
    "a1" : 313735,
    "a2" : 100597,
    "a0" : 64
  }
} ]⏎
For this new datasource every historical returns:
Copy code
[ {
  "timestamp" : "2022-06-01T05:00:00.000Z",
  "result" : {
    "a1" : 0,
    "a2" : 0,
    "a0" : 0
  }
} ]
However, I get back the data for every month for this problematic datasource except 1 when I query using Druid Query UI, so these empty API responses look odd (assuming I’m doing it correctly).
s
Maybe we should step back and look at the reindex job that you ran. Can you share the spec ?
k
Sure. Here’s the one that sometimes runs successfully (as in it results in new segments being created and queryable data returned), but also, from time to time, resulting in issues described above:
Copy code
{
  "type": "index_parallel",
  "spec": {
    "dataSchema": {
      "dataSource": "new_datasource",
      "timestampSpec": {
        "column": "__time",
        "format": "millis"
      },
      "dimensionsSpec": {
        "dimensions": [
          ...a_bunch_of_dimensions_here
        ]
      },
      "metricsSpec": [
        ...a_bunch_of_metrics_here
      ],
      "granularitySpec": {
        "type": "uniform",
        "segmentGranularity": {
          "type": "period",
          "period": "P1M",
          "timeZone": "EST"
        },
        "queryGranularity": {
          "type": "period",
          "period": "P1M",
          "timeZone": "EST"
        },
        "rollup": true,
        "intervals": ["2022-10-01T05:00:00.000Z/2022-11-01T05:00:00.000Z"]
      }
    },
    "ioConfig": {
      "type": "index_parallel",
      "inputSource": {
        "type": "druid",
        "dataSource": "origin_datasource",
        "interval": "2022-10-01T05:00:00.000Z/2022-11-01T05:00:00.000Z"
      },
      "appendToExisting": false
    },
    "tuningConfig": {
      "type": "index_parallel",
      "maxNumConcurrentSubTasks": 60,
      "forceGuaranteedRollup": false,
      "splitHintSpec": {
        "type": "maxSize",
        "maxNumFiles": 200
      },
      "partitionsSpec": {
        "type": "dynamic",
        "maxRowsPerSegment": 5000000,
        "targetRowsPerSegment": 5000000
      }
    }
  }
}
v
hmm….the new data source is derived by rolling up the old data source? Did the old data source have metrics?
s
I’m wondering if the time offset of 5 hours is causing it to create two month segments…
Where the second segment only includes 5 hours of source.
Sorry, I don’t think I was clear, the time interval is using an offset of 5 hours from the beginning and end of the interval. I’m wondering whether queryGranularity of P1M is truncating them into two different months. But the time interval mostly includes data of for one month. Then I realized, the time zone is the reason for the time shift. So probably not a good theory unless there’s a bug.
k
hmm….the new data source is derived by rolling up the old data source? Did the old data source have metrics?
“Yes” to both questions 🙂
Then I realized, the time zone is the reason for the time shift.
Yep.
Plus, I can confirm that the same ingestion spec worked for other months (2022-08 or 2022-09, for example) and querying original datasource and the new one produce the same output.
v
is this issue with same interval always?
k
Based on my observations, it’s relatively random. If we ingest 30 days worth of data with P1D granularity, some months might have only 15 (or 10, or 25) days worth of queryable data (segments are there, but they produce no data - just like that example above for that new datasource with P1M granularity). Marking those “empty” segments as unused, issuing a kill task and then re-ingesting the same data usually fixes the problem, but sometimes it takes 2-3 re-runs to actually see the data. Another thing: it doesn’t seem to matter what the ingestion source is: the original DS (daily granularity) was ingesting from S3 and the new one (monthly) ingests from daily DS - both were / are having the same issue.
It’s worse for this one month (2022-10) - I tried re-ingesting it 4 times already and still don’t see any data.
s
In the interest of figuring out if this is a metric calculation bug or if the segment is somehow incomplete. Do the counts match between source and rollup? 
count(*) from source
vs 
sum("count") from rollup
for that period?
k
Large number for the first one and empty result for the second one.
(this is with the time constraint of 2022-10).
Getting back the data for previous month (that one has been re-ingested twice to make it work).
s
Are you familiar with the segment-dump tool? https://druid.apache.org/docs/latest/operations/dump-segment.html Let's see if the segment(s) in question have data and perhaps inspect a few rows to see how they line up to the source.
k
Haven’t seen that tool before, but will give it a shot in a bit!
s
I'm also searching for bug fixes since 0.21 that might be related. This one sounds like a similar situation: https://github.com/apache/druid/pull/11189
👀 1
I'll post any others I find. Have a look to see if they might match your situation.
k
I dumped one of the segments and the data seems to be there. Here’s the first few lines from the output (dump) file:
Copy code
{"__time":1664600400000,"metric1":19.905000686645508,"metric2":null,"metric3":0,"metric4":0,"domain":"<http://domain.com|domain.com>","count":1,"opportunities":0,"user_id":xxxx,"video_id":0,"loads":1,"media_type":"video"}
(I truncated / edited the output, but I can see correct values in the original dump).
s
This one seems to hit the mark: https://github.com/apache/druid/issues/11410
k
It does look like a similar issue. Thank you, Sergio, I’ll try re-ingesting using suggested workaround.
s
Let us know how it goes.
k
I certainly will.
Doesn’t look like it helped - still getting no data back. If we were affected by this bug, wouldn’t we see 0s for our metrics? But we can definitely see properly (as in they were created and are non-empty) ingested data that’s converted to segments. It’s possible that my interpretation of this bug is incorrect.
s
You're right, the segment data seems okay which is not the same as the bug. Scanning the segment is returning nothing though... does 
SELECT count(*) FROM rollup WHERE <time condition for that interval>
return a count?
k
Nope, not for the date range in question.
I SSHed into one of our historicals and confirmed that segments for this date range are there.
So I guess historicals have been “instructed” correctly by ZK to load those segments from deep storage.
s
Trying another angle, I'm not very familiar with how __time works under different time zone. My understanding is that it will store the UTC time for it. The value in that sample row corresponds to 2022-10-01 050000 UTC which is 2022-10-01 000000 in EST. What I'm not sure about is how the filter condition translates at runtime. What time filter are you using when querying?
k
I’m using 
__time >= '2022-10-01T05:00:00.000Z' and __time < '2022-11-01T05:00:00.000Z'
It is the same (well, minus the month value) as in other successfully ingested tasks.
s
okay, so essentially the query conditions are always on UTC.
k
That is correct.
s
... still thinking... seems like a corrupt segment file. But how so? Perhaps another segment-dump with 
--dump bitmaps --decompress-bitmaps
could shed some light.
k
Cool, will do. But yeah, it’s been a really puzzling issue for us as well.
We plan to migrate to the latest version, but we’ll have to do that gradually, with proper testing in place, so it’s going to take some time. Not that it necessarily fixes this issue, but I imagine there’s a non-zero chance that it might.
s
Yeah, but it would be good to know what is happening here regardless. I keep coming back to the timezone, I understand this works for other time frames , but I'm wondering if this could be a boundary condition, so I'll keep asking about this. Do you set 
sqlTimeZone
in the query context in any of these tests?
k
No, this is not set.
v
are the number of segments significantly different for this month (2022-10)?
k
As compared to the previous month in that datasource? Not really: 870 for 2022-09 and 929 for 2022-10.
FWIW, I was able to successfully ingest that problematic date range. No significant changes’ been made - I increased the number of concurrent subtasks and reduced how many middle managers processes we allocate for batch ingestion. Doesn’t seem like that should affect the outcome, but still.
v
If I get this correct…your __time is in UTC and so are your query filters but your segment granularity and rollup are in EST?
is the druid source you are trying to rollup on also ingested with segment granularity in EST?
k
Hi Vijay, yes and yes (to both questions).
v
I am able to see this error in my setup
Copy code
2023-01-16T04:01:33,366 ERROR [task-runner-0-priority-0] org.apache.druid.indexing.common.task.IndexTask - Encountered exception in BUILD_SEGMENTS.
org.apache.druid.java.util.common.ISE: Failed to get shardSpec for interval[2019-08-19T05:00:00.000Z/2019-08-26T05:00:00.000Z]
	at org.apache.druid.indexing.common.task.ShardSpecs.getShardSpec(ShardSpecs.java:57) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.NonLinearlyPartitionedSequenceNameFunction.getSequenceName(NonLinearlyPartitionedSequenceNameFunction.java:49) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.InputSourceProcessor.process(InputSourceProcessor.java:107) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.IndexTask.generateAndPublishSegments(IndexTask.java:922) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.IndexTask.runTask(IndexTask.java:526) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.AbstractTask.run(AbstractTask.java:169) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.batch.parallel.ParallelIndexSupervisorTask.runSequential(ParallelIndexSupervisorTask.java:1199) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.batch.parallel.ParallelIndexSupervisorTask.runTask(ParallelIndexSupervisorTask.java:532) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.common.task.AbstractTask.run(AbstractTask.java:169) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:477) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner$SingleTaskBackgroundRunnerCallable.call(SingleTaskBackgroundRunner.java:449) ~[druid-indexing-service-2022.11.0-iap.jar:2022.11.0-iap]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_261]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_261]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_261]
	at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_261]
this happens only when I set rollup to EST. Not when only the segment granularity is set
@Konstantin Minevskiy the following works on my setup
Copy code
"granularitySpec": {
        "type": "uniform",
        "segmentGranularity": "WEEK",
        "queryGranularity": {
          "type": "period",
          "period": "P1W",
          "timeZone": "America/New_York",
          "origin": null
        },
        "rollup": true,
        "intervals": []
      }
can you try making the segment granularity just “MONTH” and the query granularity as you have now? My thinking is if the above works for you then it would be ok as segment granularity does not affect the result
🙌 1
k
Thanks, Vijay, I’ll try that in a bit.
We’ve migrated our 
0.21.0
cluster to the latest (
25.0.0
) version and we’re experiencing an issue where our historical processes get restarted when trying to process long-running queries. We haven’t changed anything in our Druid config. Observations: 1. Historical pods exit with status code of either 137 (sigkill) or 143 (sigterm) 2. Datadog metrics for these pods don’t show any apparent OOM events (not very different from what we observed before the migration) 3. Pods get restarted randomly - sometimes it’s just 1 or 2 and sometimes all of them at the same time.
v
Just to close the loop here. This issue got sorted after increasing the number of http threads
🙏 2
s
Just to add a bit to why this happened. Druid 25 defaults to http based segment announcement, task management and coordinator/historical communication. This puts more work on the http threads and hence the need to increase them.
🙌 2
k
We really appreciate all the help we’ve received. Thank you, @Vijay Narayanan and @Sergio Ferragut.
🙏 1
Open in Slack
PreviousNext
Powered by