https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# general
s
This message was deleted.
j
Moved to #C0309C9L90D
g
you can do 
druid.segmentCache.lazyLoadOnStart = true
, which moves the work to query time instead of server startup time
ref: https://druid.apache.org/docs/latest/configuration/index.html
Whether or not to load segment columns metadata lazily during historical startup. When set to true, Historical startup time will be dramatically improved by deferring segment loading until the first time that segment takes part in a query, which will incur this cost instead.
j
We're giving the option a try now. Thanks.
This did not improve things
To be clear; we have log lines like this:
Copy code
2022-12-03T00:38:57,281 INFO [main] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment cache file [51944/76371] ...
g
do you have a new enough version such that this option is available? i'm surprised it has no effect
j
The parameter was definitely detected by Druid
Copy code
2022-12-03T00:34:26,200 INFO [main] org.apache.druid.cli.CliHistorical - * druid.segmentCache.lazyLoadOnStart: true
We're running 
apache-druid-0.23.0
I notice that it's loading everything from the infoDir
g
yeah, it would do that even w/ the lazy load setting
the lazy load setting just speeds up the process by loading not as much stuff
like, it won't load the metadata for each column, for example
j
Oh, well that's what takes hours to startup. The metadata I've never had any issue with that taking any time whatsoever.
g
the parade of "Loading segment cache file" (from 0 to 76371) is what takes hours?
j
Correct
I'm planning to set 
druid.segmentCache.numBootstrapThreads
to 
num_cores
I measured it as being able to read around 17/second.
Something you may find interesting though: if we interrupt this process (say, to apply a new config property) then it seems to catch up VERY quickly to where it left off last time. In all, some server restarts go by in seconds and others in hours.
FYI - org.eclipse.jetty.server.Server - Started @6913615ms
g
are you setting 
druid.segmentCache.numThreadsToLoadSegmentsIntoPageCacheOnDownload
or 
druid.segmentCache.numThreadsToLoadSegmentsIntoPageCacheOnBootstrap
?
these are configs to prepopulate the page cache with segment data on startup — it's going to force a scan off disk of the entire segment during startup
i believe they're off by default
but if set they would extend startup time quite a bit
j
Nope, we don't set those
g
(the purpose is to make query performance more regular at the cost of startup time — they're like the opposite direction of lazy loading)
j
Before today we just set locations but now we set these three:
Copy code
$ egrep segmentCache historical/runtime.properties
druid.segmentCache.locations=[{"path":"/data/tripstack/druid/segment-cache","maxSize":"1000g"}]
druid.segmentCache.lazyLoadOnStart = true
druid.segmentCache.numBootstrapThreads = 16
g
Just to be clear it's not the 
Loading segment[x/y]
that are taking time?
How fast do those go by?
j
With 16 threads allocated we're now getting just under 90/second
g
It seems pretty odd that the 
Loading segment cache file
stuff would take so much time, since it isn't doing much. Just loading the descriptor json files from the info dir
the 
Loading segment[x/y]
parade is doing the actual segment loading
j
Example log line:
Copy code
2022-12-03T01:29:46,685 INFO [main] org.apache.druid.server.coordination.SegmentLoadDropHandler - Loading segment cache file [55566/78304][/data/tripstack/druid/segment-cache/info_dir/best-booking-emails_2022-07-10T23:00:00.000Z_2022-07-11T00:00:00.000Z_2022-09-14T15:07:20.565Z_86].
Loading segment[x/y]
also takes some time but seems to go by MUCH faster
g
does anything get logged between the 
Loading segment cache file
lines, or just a parade of them with nothing in between?
j
Nope. Just a parade of these with nothing in between.
g
how big are the individual files in your 
info_dir
?
j
I just noticed these are on the 
main
thread. However it does seem to be going faster now that we've increased the 
druid.segmentCache.numBootstrapThreads
g
not much is being done except reading them all in sequence
seems quite odd it would take appreciable amounts of time
unless they're super jumbo for some reason? usually they're a few KB each so even 100,000 of them would be just a few hundred MB
which shouldn't take hours to read…
j
under 1K
Oh, some are 4K
Let me sort them by size
Biggest ones are 6K but the majority are around 4.7K
g
very strange
also out of curiosity i'm wondering how fast i/o is on the volume
try 
find [path to info_dir] -type f -exec cat {} \; > /dev/null
👀 1
to see how long it takes to simply read through all the files
j
Okay with 16 threads assigned the 
Loading segment[x/y]
took about 4 minutes so nearly all the work is done in 
Loading segment cache file [x/y]
Copy code
$ date; time find info_dir -type f -exec cat {} \; > /dev/null; date
Fri 02 Dec 2022 08:42:14 PM EST

real	1m56.704s
user	1m7.776s
sys	0m49.148s
Fri 02 Dec 2022 08:44:11 PM EST
g
curious
ok, now i'm interested in a flame graph 🙂 if you can capture one post it here & i'll have a look
👀 1
j
Unfortunately this is a production system and we are just coming out of maintenance now so I won't be able to get a flame graph today.
g
well, remember it next time if you can; we'll be here 🙂
🙌 1
j
Looking back in logs it's notable that just before the parade of 
Loading segment cache file
logs we had an error from ZK
Copy code
2022-12-03T01:43:37,309 ERROR [main-EventThread] org.apache.curator.framework.imps.EnsembleTracker - Invalid config event received: {server.1=bidruid-zk01:2888:3888:participant, version=0, server.3=bidruid-zk03:2888:3888:participant, server.2=bidruid-zk02:2888:3888:participant}
a
is it possible to post the contents of a cache file that is known to take time?
j
@Abhishek Agarwal There's no particular file that takes noticeably longer than others. It's just that Druid slowly processes them at a rate of ~ 400 KB/sec so it takes forever to get through > 70K of them. Here's a typical example:
efoe-search-started-events_2022-08-16T00:00:00.000Z_2022-08-17T00:00:00.000Z_2022-08-17T06:56:26.428Z_11
g
fwiw, I just tried deserializing that (on the off chance it hit some perf issue) but that's not it. the deserialize rate is good (10s of thousands of JSONs like that per second)
✅ 1
o
Hi, I'm interrested about this behavior.... so finaly how did you solved that ? just by the 
druid.segmentCache.numBootstrapThreads
and lazy loading ?
Open in Slack
PreviousNext
Powered by