https://pinot.apache.org/ logo
Join Slack
Powered by
Hi, I am trying JSON Index in pinot tag is a json ...
# troubleshooting
a
Hi, I am trying JSON Index in pinot tag is a json column containing, a list called Tags Eg : 
{"Tags":["TAG1","TAG3", "TAG2"]}
Running query like below :
Copy code
select sum(amount) as amt from transactions
where from_user_id = 'some id'
and JSON_MATCH(tag, '"$.Tags[*]"=''FD''')
Created sorted index on from_user_id(string) and json index on tag Explain plan shows both the index are used The queries take ~500 ms, Is there a way to improve this? Some obvious optimisation I am missing
k
Do you have the response metadata
a
yes
Copy code
"numServersQueried": 2,
  "numServersResponded": 2,
  "numSegmentsQueried": 13,
  "numSegmentsProcessed": 13,
  "numSegmentsMatched": 13,
  "numConsumingSegmentsQueried": 0,
  "numDocsScanned": 69,
  "numEntriesScannedInFilter": 6,
  "numEntriesScannedPostFilter": 69,
  "numGroupsLimitReached": false,
  "totalDocs": 100000000,
  "timeUsedMs": 502,
  "offlineThreadCpuTimeNs": 0,
  "realtimeThreadCpuTimeNs": 0,
  "offlineSystemActivitiesCpuTimeNs": 0,
  "realtimeSystemActivitiesCpuTimeNs": 0,
  "offlineResponseSerializationCpuTimeNs": 0,
  "realtimeResponseSerializationCpuTimeNs": 0,
  "offlineTotalCpuTimeNs": 0,
  "realtimeTotalCpuTimeNs": 0,
The response time is also varying hugely if I change the tag I am querying for, this query took ~150ms Only changed FD -> MF,
Copy code
select sum(amount) as amt from transactions
where from_user_id = 'some id'
and JSON_MATCH(tag, '"$.Tags[*]"=''MF''')
Metadata
Copy code
"exceptions": [],
  "numServersQueried": 2,
  "numServersResponded": 2,
  "numSegmentsQueried": 13,
  "numSegmentsProcessed": 13,
  "numSegmentsMatched": 6,
  "numConsumingSegmentsQueried": 0,
  "numDocsScanned": 10,
  "numEntriesScannedInFilter": 2,
  "numEntriesScannedPostFilter": 10,
  "numGroupsLimitReached": false,
  "totalDocs": 100000000,
  "timeUsedMs": 158,
  "offlineThreadCpuTimeNs": 0,
  "realtimeThreadCpuTimeNs": 0,
  "offlineSystemActivitiesCpuTimeNs": 0,
  "realtimeSystemActivitiesCpuTimeNs": 0,
  "offlineResponseSerializationCpuTimeNs": 0,
  "realtimeResponseSerializationCpuTimeNs": 0,
  "offlineTotalCpuTimeNs": 0,
  "realtimeTotalCpuTimeNs": 0,
  "segmentStatistics": [],
It matched only 6 segments, makes sense that it was faster
k
This should be few milliseconds.. can you share the cluster config? Men cpu disk/ssd/ebs
a
This is a test setup
Copy code
m5x.large ec2 instances * 4
4 cores, 16GB ram
50 GB ssd (Can increase this but still have ample free space)
S3 deep store configured
4 * Brokers and Servers on same ec2 host
1 Controller is hosted along with broker and server in one ec2 host
2 replica groups * 2 hosts each
k
yeah, this looks good. can you remove JSON_MATCH predicate and try the query
r
do you know the frequency distribution of your tag values? Is FD much more common that MF?
a
This is randomly generated, I hoped it to be truly random tag list The counts are FD : 74794853
Copy code
select count(*) from transactions
where JSON_MATCH(tag, '"$.Tags[*]"=''FD''')
MF : 12466054
Copy code
select count(*) from transactions
where JSON_MATCH(tag, '"$.Tags[*]"=''MF''')
FD is definitely more frequent
r
I could suggest another approach to reduce latency slightly, but I think this is a pattern we could optimise for better so we make better use of the user id filtering
extracting the tags array into an MV column and putting a bitmap index on that would be better than JSON index here
a
yes created a new mv column of string type Hoping that 
JSONPATH(tag, '$.Tags')
transforms it to multivalued col, just reloaded all segments
Got a execption, let me try fix this
Copy code
Caught exception while creating derived column: tags_mv with transform function: JSONPATH(tag, '$.Tags')
java.lang.ClassCastException: null
r
you can use jsonPathArrayDefaultEmpty
a
yes used a similar function 
JSONPATHARRAY(\"tag\", '$.Tags[*]')
albeit reloading segments was hard on servers, 3 out of 4 docker containers restarted had to restart a server, still one server is not happy Keeps throwing this error
Copy code
[BaseServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceStatusCallback:IdealStateAndCurrentStateMatchServiceStatus
Callback:partition=transactions_OFFLINE_1617235200701_1619827199799_0, expected=ONLINE, found=OFFLINE, creationTime=1643910462990, modifiedTime=1643910639645, version=6, waitingFor=CurrentStateMatch, resource=transactions_OFFLINE, numResourcesLeft=1, num
TotalResources=3, minStartCount=3,;IdealStateAndExternalViewMatchServiceStatusCallback:Init;;
r
can you default to empty?
a
yes, changed the config, started segment reload Any pointers on preventing server restarts during segment reload? Is it possible to only reload segments in one replica group?
Interesting, I think theses results are from older segments where transform function was 
JSONPATHARRAY
Results got messed up after first null tag
Hi, I tried restarting the server it starts timing out after downloading the segment, I think its trying to created the tags_mv column using the transformation config But after that continues to print below timeout log
Copy code
2022/02/04 06:44:19.429 INFO [V3DefaultColumnHandler] [HelixTaskExecutor-message_handle_thread] Starting default column action: ADD_DIMENSION on column: tags_mv
2022/02/04 06:44:22.410 INFO [BaseServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: MultipleCallbackServiceStatusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=transactions_OFFLINE_1617235200701_1619827199799_0, expected=ONLINE, found=OFFLINE, creationTime=1643956885876, modifiedTime=1643957050869, version=6, waitingFor=CurrentStateMatch, resource=transactions_OFFLINE, numResourcesLeft=1, numTotalResources=3, minStartCount=3,;IdealStateAndExternalViewMatchServiceStatusCallback:Init;;PinotServiceManagerStatusCallback:Started;
The log ends with this warning
Copy code
2022/02/04 06:51:37.508 WARN [BaseServerStarter] [Start a Pinot [SERVER]] Service status has not turned GOOD within 585408ms: MultipleCallbackServiceStatusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=transactions_OFFLINE_1617235200701_1619827199799_0, expected=ONLINE, found=OFFLINE, creationTime=1643956885876, modifiedTime=1643957050869, version=6, waitingFor=CurrentStateMatch, resource=transactions_OFFLINE, numResourcesLeft=1, numTotalResources=3, minStartCount=3,;IdealStateAndExternalViewMatchServiceStatusCallback:Init;;PinotServiceManagerStatusCallback:Started;
I had another table its segments loaded successfully. How can we recover from this state?
From controller logs it seems the server's http server is down.
Copy code
2022/02/04 07:03:42.809 WARN [MultiGetRequest] [restapi-multiget-thread-983] Caught 'java.net.SocketTimeoutException: Read timed out' while executing GET on URL: <http://10.9.3.206:8097/table/transcript_OFFLINE/size>
2022/02/04 07:03:42.809 ERROR [CompletionServiceHelper] [grizzly-http-server-0] Connection error
java.util.concurrent.ExecutionException: java.net.SocketTimeoutException: Read timed out
Its now declared dead in pinot ui (was alive for some time)
Got this log in server startup :
Copy code
manual-pinot-server-3 | 2022/02/04 06:52:34.274 ERROR [StartServiceManagerCommand] [Start a Pinot [SERVER]] Failed to start a Pinot [SERVER] at 671.903 since launch
manual-pinot-server-3 | org.apache.helix.HelixException: fail to set config. cluster: defaultpinot is NOT setup.
says cluster not setup, the name is correct and other 3 servers are connecting to defaultpinot cluster
cpu is continuously at 100% while the timeouts happen
GC logs gives some hints, xmx 4G
Copy code
[431.180s][info][gc] GC(227) Pause Young (Concurrent Start) (G1 Evacuation Pause) 4088M->4088M(4096M) 12.911ms
[431.180s][info][gc] GC(229) Concurrent Cycle
[436.696s][info][gc] GC(228) Pause Full (G1 Evacuation Pause) 4088M->4073M(4096M) 5515.255ms
[436.700s][info][gc] GC(229) Concurrent Cycle 5519.263ms
[436.714s][info][gc] GC(230) To-space exhausted
xmx 6G
Copy code
[263.348s][info][gc] GC(151) Pause Young (Normal) (G1 Evacuation Pause) 6138M->6138M(6144M) 131.588ms
[271.732s][info][gc] GC(152) Pause Full (G1 Evacuation Pause) 6138M->5922M(6144M) 8383.175ms
[271.936s][info][gc] GC(153) To-space exhausted
[271.937s][info][gc] GC(153) Pause Young (Concurrent Start) (G1 Evacuation Pause) 6136M->6136M(6144M) 125.753ms
[271.937s][info][gc] GC(155) Concurrent Cycle
xmx 8G
Copy code
[231.592s][info][gc] GC(165) Pause Young (Normal) (G1 Evacuation Pause) 8183M->8183M(8192M) 220.512ms
[242.595s][info][gc] GC(166) Pause Full (G1 Evacuation Pause) 8183M->7819M(8192M) 11002.538ms
[242.595s][info][gc] GC(164) Concurrent Cycle 11426.133ms
[242.943s][info][gc] GC(167) To-space exhausted
no effect of increasing heap size
r
can you take a profile during startup?
did you say which pinot version you were using btw?
a
Its 10 days old (26-27 Jan) nightly docker image , digest a6c14285abf4
could you please share the command for taking profile I should run this inside the container right?
The exact docker image : apachepinot/pinot:0.10.0-SNAPSHOT-e7ea235a1e-20220124-jdk11
This is the profile cmd, I remeber from other thread
Copy code
jcmd <pid> JFR.start duration=60s settings=profile filename=startup_profile.jfr
ran jcmd for pid 1 (I think pid 1 is the parent process id for server, otherwise I can see many processes of server running with htop) 
jcmd 1 JFR.start duration=60s settings=profile filename=startup_profile.jfr
Copy code
1:
com.sun.tools.attach.AttachNotSupportedException: Unable to open socket file /proc/1/root/tmp/.java_pid1: target process 1 doesn't respond within 10500ms or HotSpot VM not loaded
	at jdk.attach/sun.tools.attach.VirtualMachineImpl.<init>(VirtualMachineImpl.java:100)
	at jdk.attach/sun.tools.attach.AttachProviderImpl.attachVirtualMachine(AttachProviderImpl.java:58)
	at jdk.attach/com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:207)
	at jdk.jcmd/sun.tools.jcmd.JCmd.executeCommandForPid(JCmd.java:114)
will give this another try after recreating container
r
alternatively enable jfr with jvm args:
Copy code
-XX:+FlightRecorder -XX:StartFlightRecording=duration=300s,settings=profile,filename=filename.jfr
you can dump the recording with jcmd, or wait 5 mins
a
i have restarted the server, will run jcmd when i'll see heap getting filled from gc logs it takes few min to reach that state
@Richard Startin the jvm profile
startup_profile.jfr
r
thanks, will take a look
if this is what I think it is, it's fixed on master
a
Thanks! shall I pull in the new image? or keep this running incase we want to debug further
r
I need to check, give me 5 mins
the profile looks ok actually
there are a few things I fixed in the jsonpath library which has been released and is used on master now, so it might be worth taking the latest image, but this doesn't look like a performance problem
a
sure will pull in the new image the server is still at 100% cpu and jvm logs saying 
To-space exhausted
will share another profile with new image
sending new profile, the issue persists with new image
server_startup.jfr
👀 1
r
looks like the jsonpath library is still struggling
a
oh, i think dropping and recreating table is the only option now the segments are in s3, will push them 1 by 1 this should hopefully prevent crash
r
most of the time is spent in MD5 checksumming
I think AWS contributed an MD5 intrinsic in the last few years, it might help
it's in JDK16 
-XX:+UseMD5Intrinsics
💡 1
a
most of the time is spent in MD5 checksumming -> does it mean server created the new column using jsonpath but is failing due to creating checksum of segment?
it's in JDK16 
-XX:+UseMD5Intrinsics
-> pinot runs on jdk 11 only right that the jvm in docker image
r
it's actually being backported to 11 now https://github.com/openjdk/jdk11u-dev/pull/806
so we can't make use of it yet, but this should improve soon
a
Thanks for the info one doubt most of the time is spent in MD5 checksumming -> does it mean server created the new column using jsonpath but is failing due to creating checksum of segment?
r
the checksumming is part of the S3 download
a
oh, I thought it was related to the gc issue logs indicated that the segments are downloaded from s3 after that server tried to do ADD_DIMENSION, the issue started
Copy code
2022/02/04 06:44:19.429 INFO [V3DefaultColumnHandler] [HelixTaskExecutor-message_handle_thread] Starting default column action: ADD_DIMENSION on column: tags_mv
2022/02/04 06:44:22.410 INFO [BaseServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: MultipleCallbackServiceStatusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=transactions_OFFLINE_1617235200701_1619827199799_0, expected=ONLINE, found=OFFLINE, creationTime=1643956885876, modifiedTime=1643957050869, version=6, waitingFor=CurrentStateMatch, resource=transactions_OFFLINE, numResourcesLeft=1, numTotalResources=3, minStartCount=3,;IdealStateAndExternalViewMatchServiceStatusCallback:Init;;PinotServiceManagerStatusCallback:Started;
transform config for tag_mv
Copy code
{
  "columnName": "tags_mv",
  "transformFunction": "JSONPATHARRAYDEFAULTEMPTY(\"tag\", '$.Tags[*]')"
}
r
the GC issue appears to be caused by JsonPath allocating a lot
about 50:50 S3 client and JsonPath allocating 40GB byte[] during the profile
14GB String from JsonPath
a
Thanks for the insights, I need to learn debugging jfr profile 🙂 The solution that I can think is to rerun data ingestion job, it will create the derived column (I think) and persist it to segments Then servers will have to only download the segment and create indexes Can indexing cause memory issue? i saw that inverted index are created on servers after downloading segments
r
potentially in your case because you have poor selectivity on a lot of these tags, but I don't see much 
RoaringBitmap
in the allocation profile
< 2GB all told, compared to the numbers for byte[] and String (and others)
more like 4GB actually, but it's not the problem here
the hard thing is these allocations are all in our dependencies, and it took 6 months to get JsonPath released with some improvements, I doubt S3 client will ever be super efficient
I'll ask @Mayank if there's anything else you can do to resolve this later, but we know now why you have memory problems and where it's coming from
thankyou 1
a
the bitmap/dictionay part is default right? will an inverted index be better? can't find much info around indexing mv columns
r
bitmap index = inverted index
according to the profile, the index isn't the problem anyway
I think we should try to improve jsonpath extraction, it would help what you're trying to do here
a
the initial config had tag_mv 
invertedIndexColumns
but I removed it later Is it default for MV column?
r
no it's not default
a
interesting, the memory alloc for roaring bitmap must be for to_user_id col on which i had inverted index
may be if server tried loading segments one by one we can reduce the memory requirement, I think thats what happen on segment reload (but not during server start) the segments are >400 MB (6-7M records) in size, 6 were allocated to this server. the size might also be a problem
Open in Slack
PreviousNext
Powered by