https://pinot.apache.org/ logo
Join Slack
Powered by
i have my servers running on k8s helm with the fol...
# troubleshooting
x
i have my servers running on k8s helm with the following resources:
Copy code
# <https://docs.pinot.apache.org/operators/tutorials/deployment-pinot-on-kubernetes#jvm-setting>
resources:
  requests:
    cpu: 4
    memory: 10G
  limits:
    cpu: 4
    memory: 10G
how do i diagnose the cause of slow queries based on the logs?
Copy code
Processed requestId=93,table=eventsv2-2021-09_OFFLINE,segments(queried/processed/matched/consuming)=10/10/10/-1,schedulerWaitMs=0,reqDeserMs=1,totalExecMs=4883,resSerMs=1,totalTimeMs=4885,minConsumingFreshnessMs=-1,broker=Broker_pinot-broker-0.pinot-broker-headless.pinot.svc.cluster.local_8099,numDocsScanned=1194957,scanInFilter=422644416,scanPostFilter=1194957,sched=fcfs,threadCpuTimeNs=0

...

Processed requestId=93,table=eventsv2-2021-09_OFFLINE,segments(queried/processed/matched/consuming)=10/10/10/-1,schedulerWaitMs=0,reqDeserMs=1,totalExecMs=4414,resSerMs=0,totalTimeMs=4415,minConsumingFreshnessMs=-1,broker=Broker_pinot-broker-0.pinot-broker-headless.pinot.svc.cluster.local_8099,numDocsScanned=1156729,scanInFilter=422867040,scanPostFilter=1156729,sched=fcfs,threadCpuTimeNs=0
the offending query is:
Copy code
SELECT user, COUNT(*) FROM "eventsv2-2021-09" WHERE IN_SUBQUERY(cell, 'SELECT ID_SET(location) FROM dimTable WHERE id IN (...)') = 1 GROUP BY user HAVING COUNT(user) >= 20 LIMIT 10000000
i have 
dictionary, forward-index, inverted-index
indexes on columns user and cell
Copy code
Table Name: eventsv2-2021-09_OFFLINE
Reported Size: 41665794922
Copy code
Table Name: dimTable_OFFLINE
Reported Size: 550871750
r
hi can you post the tracing output for the query please (select the option, visible in the JSON view)
that will probably point to a slow operator, which will probably indicate a missing index, but if it doesn't it would be good to take a profile afterwards
x
oh it’s really large
distinct count select
Copy code
SELECT DISTINCT(COUNT(user)) FROM "eventsv2-2021-09" WHERE IN_SUBQUERY(cell, 'SELECT ID_SET(location) FROM dimTable WHERE id IN (...)') = 1 LIMIT 10000000
Copy code
{
  "numServersQueried": 10,
  "numServersResponded": 10,
  "numSegmentsQueried": 100,
  "numSegmentsProcessed": 100,
  "numSegmentsMatched": 100,
  "numConsumingSegmentsQueried": 0,
  "numDocsScanned": 11651626,
  "numEntriesScannedInFilter": 4221307776,
  "numEntriesScannedPostFilter": 11651626,
  "numGroupsLimitReached": false,
  "totalDocs": 4221307776,
  "timeUsedMs": 8334,
}
tracing_output_1_server
i dont know if this is helpful
how should i interpret it?
r
it's large because there's an entry for every block (of documents) of every stage of every operator
x
2 different queries
group by having
Copy code
SELECT user, COUNT(*) FROM "eventsv2-2021-09" WHERE IN_SUBQUERY(cell, 'SELECT ID_SET(location) FROM dimTable WHERE id IN (...)') = 1 GROUP BY user HAVING COUNT(user) >= 20 LIMIT 10000000
tracing_output
r
I'll get back to you tomorrow morning
something else you can do is take a profile during query execution if you have access to the box:
Copy code
jcmd <server pid> JFR.start duration=60s filename=slowquery.jfr settings=profile
x
can i profile an already running server?
is there a guide?
r
that command will produce a .jfr file if you have a JDK on the box
x
im running it on kubernetes
r
is this in production?
x
so each server is running on a pod
nah, staging
r
sure do something like 
kubectl exec -it -n <namespace> <pod-name> -- bash
then run that jcmd command
x
ok got it
thanks richard!
i have 10 servers
will profiling 1 be a good enough sample?
r
yes if you can direct load at it
x
👍
r
the trace is pretty unwieldy, but it looks like the bottlneck is bitmap iteration (look for 
DocIdSetOperator
) which might suggest an inverted index which isn't very selective
x
there is an inverted index:
i have 
dictionary, forward-index, inverted-index
 indexes on columns user and cell
r
what version are you on? 0.9 has an explain plan - just prepend 
explain
x
0.9.2
r
actually it's not using the inverted index because there is no 
BitmapBasedFilterOperator
can you run an explain query then?
x
but prepending explain to my query results in this:
Copy code
ProcessingException(errorCode:150, message:PQLParsingError:
org.apache.pinot.sql.parsers.SqlCompilationException: Caught exception while parsing query: EXPLAIN SELECT userid_int, COUNT(*) FROM "eventsv2-2021-09" WHERE IN_SUBQUERY(cell_id, 'SELECT ID_SET(location) ...
	at org.apache.pinot.sql.parsers.CalciteSqlParser.compileCalciteSqlToPinotQuery(CalciteSqlParser.java:302)
	at org.apache.pinot.sql.parsers.CalciteSqlParser.compileToPinotQuery(CalciteSqlParser.java:106)
	at org.apache.pinot.sql.parsers.CalciteSqlCompiler.compileToBrokerRequest(CalciteSqlCompiler.java:35)
	at org.apache.pinot.controller.api.resources.PinotQueryResource.getQueryResponse(PinotQueryResource.java:166)
...
Caused by: org.apache.calcite.sql.parser.SqlParseException: Encountered "EXPLAIN SELECT" at line 1, column 1.
Was expecting one of:
    "SET" ...
    "WITH" ...
    "+" ...
...
Caused by: org.apache.calcite.sql.parser.babel.ParseException: Encountered "EXPLAIN SELECT" at line 1, column 1.
Was expecting one of:
    "SET" ...
    "WITH" ...
    "+" ...)
r
sorry it's 
EXPLAIN PLAN FOR
x
mmm:
Copy code
java.lang.ClassCastException: class org.apache.calcite.sql.SqlExplain cannot be cast to class org.apache.calcite.sql.SqlSelect (org.apache.calcite.sql.SqlExplain and org.apache.calcite.sql.SqlSelect are in unnamed module of loader 'app')
👀 1
r
also do you have the response metadata (in the json view) from the query without running the explain plan? (numDocsScanned etc.)
x
first query was for distinct count select, second query is for group by having
r
the response metadata would be very useful
x
i’ve edited the post with tracing output for my first distinct count select query with metadata: https://apache-pinot.slack.com/archives/C011C9JHN7R/p1641510414015700?thread_ts=1641470475.007000&amp;cid=C011C9JHN7R
r
ok, so definitely not using the index:
Copy code
"numDocsScanned": 11651626,
  "numEntriesScannedInFilter": 4221307776,
  "numEntriesScannedPostFilter": 11651626,
x
sorry, how did you know that?
r
so the traces don't have the right operator name in, and it looks like it's scanning
x
why is that though? im using a subquery to retrieve an idSet for 
cell
, and i have the indexes for 
cell
am i doing something wrong?
r
thanks, it confirms my suspicion - the problem is the ID_SET
50% of time in here:
Copy code
int[] intValues = _transformFunction.transformToIntValuesSV(projectionBlock);
        for (int i = 0; i < length; i++) {
          _results[i] = _idSet.contains(intValues[i]) ? 1 : 0;
        }
        break;
x
how do you visualize the jfr file?
r
which isn't surprising if the RoaringBitmap is large
JMC
basically, there's not going to be a way to make that query fast without code changes, the distinct operator shows up in the trace and the profile and it uses RoaringBitmap inefficiently. I will create an issue for this and improve it.
in the meantime, think about how you can write the query differently
x
mm
thats for the first query
i can get you the profile for the second slow groupby query
r
what indexing do you have on 
id
?
x
Copy code
dictionary	forward-index	inverted-index
r
if id is the sorted column (I think it might be because of all the RangeDocIdSetOperator blocks in the trace) you can delete the inverted index because it won't be used
x
i see
i do not know why, but my table schema does not specify any indexing
it looks like this:
Copy code
"tableIndexConfig": {
      "rangeIndexVersion": 1,
      "autoGeneratedInvertedIndex": false,
      "createInvertedIndexDuringSegmentGeneration": false,
      "sortedColumn": [
        "id"
      ],
      "loadMode": "MMAP",
      "enableDefaultStarTree": false,
      "enableDynamicStarTreeCreation": false,
      "aggregateMetrics": false,
      "nullHandlingEnabled": false
    },
but index status shows:
r
oh - that's a little misleading, because it's sorted it automatically has a sorted index which is a kind of inverted index
I created this ticket, I will do some work probably in the next month to speed IdSet up, but I think rethinking the query will get you further https://github.com/apache/pinot/issues/7980
x
hmm, what are you suggesting when you say “rethinking the query”?
i need to get the mapping from the dimension table to transform 
cell
in my fact table before i apply it as a predicate
r
I mean is there a way you can model the data differently?
x
no, its not possible
the dimension table will updated from time to time
it would be too expensive to rebuild the fact table every time new mappings come in
m
cc @Jackie for the 
IN_ID_SET
transform function being slow
x
would indexing help here? im still unclear as to the previous statement:
actually it's not using the inverted index because there is no 
BitmapBasedFilterOperator
Open in Slack
PreviousNext
Powered by