I got some problem with query result I run the same query st Apache Pinot #troubleshooting

I got some problem with query result. I run the sa...

Phúc Huỳnh

06/10/2021, 10:57 AM

I got some problem with query result. I run the same query statement

Copy code

select count(*) from RuleLogsUAT

But got timeout & difference result per request. Here is the request log

Copy code

requestId=43,table=RuleLogsUAT,timeMs=10001,docs=210279/210377,entries=0/0,segments(queried/processed/matched/consuming/unavailable):21/18/18/2/0,consumingFreshnessTimeMs=1623319344461,servers=4/5,groupLimitReached=false,brokerReduceTimeMs=0,exceptions=0,serverStats=(Server=SubmitDelayMs,ResponseDelayMs,ResponseSize,DeserializationTimeMs);pinot-server-1_R=1,-1,0,0;pinot-server-2_R=2,6,250,0;pinot-server-0_R=2,6,250,0;pinot-server-0_O=1,7,230,0;pinot-server-1_O=2,11,230,0,query=select count(*) from RuleLogsUAT,offlineThreadCpuTimeNs=1548682,realtimeThreadCpuTimeNs=1908620
requestId=44,table=RuleLogsUAT,timeMs=10002,docs=44807/44811,entries=0/0,segments(queried/processed/matched/consuming/unavailable):19/17/17/3/0,consumingFreshnessTimeMs=1623319158004,servers=4/5,groupLimitReached=false,brokerReduceTimeMs=0,exceptions=0,serverStats=(Server=SubmitDelayMs,ResponseDelayMs,ResponseSize,DeserializationTimeMs);pinot-server-1_R=1,10,250,0;pinot-server-2_R=1,7,250,0;pinot-server-0_R=1,8,250,0;pinot-server-2_O=1,-1,0,0;pinot-server-1_O=1,11,230,0,query=select count(*) from RuleLogsUAT,offlineThreadCpuTimeNs=1211610,realtimeThreadCpuTimeNs=1412400
requestId=45,table=RuleLogsUAT,timeMs=10002,docs=73633/73731,entries=0/0,segments(queried/processed/matched/consuming/unavailable):23/20/20/3/0,consumingFreshnessTimeMs=1623319158007,servers=4/5,groupLimitReached=false,brokerReduceTimeMs=0,exceptions=0,serverStats=(Server=SubmitDelayMs,ResponseDelayMs,ResponseSize,DeserializationTimeMs);pinot-server-1_R=0,5,250,0;pinot-server-2_R=0,8,250,0;pinot-server-0_R=0,8,250,0;pinot-server-0_O=0,7,230,0;pinot-server-1_O=1,-1,0,0,query=select count(*) from RuleLogsUAT,offlineThreadCpuTimeNs=655059,realtimeThreadCpuTimeNs=1141471
requestId=46,table=RuleLogsUAT,timeMs=10002,docs=44807/44811,entries=0/0,segments(queried/processed/matched/consuming/unavailable):19/17/17/3/0,consumingFreshnessTimeMs=1623319158004,servers=4/5,groupLimitReached=false,brokerReduceTimeMs=0,exceptions=0,serverStats=(Server=SubmitDelayMs,ResponseDelayMs,ResponseSize,DeserializationTimeMs);pinot-server-1_R=1,5,250,0;pinot-server-2_R=1,7,250,0;pinot-server-0_R=1,6,250,0;pinot-server-2_O=1,-1,0,0;pinot-server-1_O=1,7,230,0,query=select count(*) from RuleLogsUAT,offlineThreadCpuTimeNs=417430,realtimeThreadCpuTimeNs=1821230

Neha Pawar

06/10/2021, 4:38 PM

are all your servers healthy? only 4 servers are responding

servers=4/5

, hence the difference in result. You can check whats wrong with 1 server

Neha Pawar

06/10/2021, 4:40 PM

looks like a different server everytime. are they restarting?

Phúc Huỳnh

06/11/2021, 2:21 AM

hmm, i only have 3 server, but idk why pinot query 4/5 server 🤔

Phúc Huỳnh

06/11/2021, 2:22 AM

Screen Shot 2021-06-11 at 9.22.11 AM.png

Neha Pawar

06/11/2021, 2:30 AM

is this a hybrid table? have you tagged the servers as both _REALTIME and as _OFFLINE?

Phúc Huỳnh

06/11/2021, 2:30 AM

yes, it’s hybrid table

Phúc Huỳnh

06/11/2021, 2:40 AM

hmm, how

numServersQueried

was determine ? It’s zk configs ?

Neha Pawar

06/11/2021, 2:48 AM

you probably have tagged your servers as both tenant_OFFLINE and tenant_REALTIME. Can you check in ZK browser or instance configs?

Neha Pawar

06/11/2021, 2:48 AM

if you’ve tagged it as both, then it will get counted as once for realtime and once for offline

Phúc Huỳnh

06/11/2021, 2:52 AM

yes. my servers has both tags

DefaultTenant_OFFLINE, DefaultTenant_REALTIME

Phúc Huỳnh

06/11/2021, 2:53 AM

in realtime_table - segments exists in 3 server, in offline table - segments exists in 2 server. That’s reason why numServersQueried = 5. That’s ok

Phúc Huỳnh

06/11/2021, 2:54 AM

all my server is healthy, but why 1 server responding timeout 🤔

Neha Pawar

06/11/2021, 3:00 AM

It's always either server 1 or server 2, the ones that have both. Any errors in those server logs? Are those server high on memory utilization?

Neha Pawar

06/11/2021, 3:00 AM

@Mayank ^^ what might be some possible reasons those servers cannot do even a count * ?

Phúc Huỳnh

06/11/2021, 3:02 AM

Copy code

Timed out while polling results block, numBlocksMerged: 0 (query: QueryContext{_tableName='RuleLogsUAT_OFFLINE', _selectExpressions=[count(*)], _aliasList=[null], _filter=created_at_days_epoch <= '18761', _groupByExpressions=null, _havingFilter=null, _orderByExpressions=null, _limit=10, _offset=0, _queryOptions={responseFormat=sql, groupByMode=sql, timeoutMs=9998}, _debugOptions=null, _brokerRequest=BrokerRequest(querySource:QuerySource(tableName:RuleLogsUAT_OFFLINE), pinotQuery:PinotQuery(dataSource:DataSource(tableName:RuleLogsUAT_OFFLINE), selectList:[Expression(type:FUNCTION, functionCall:Function(operator:COUNT, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:*))]))], filterExpression:Expression(type:FUNCTION, functionCall:Function(operator:LESS_THAN_OR_EQUAL, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:created_at_days_epoch)), Expression(type:LITERAL, literal:<Literal stringValue:18761>)])), queryOptions:{responseFormat=sql, groupByMode=sql, timeoutMs=9998}))})

I think this is errors logs

Phúc Huỳnh

06/11/2021, 3:03 AM

it’s happen on server-1

Mayank

06/11/2021, 3:04 AM

Is this production? If so, why do you have both realtime and offline on same server?

Phúc Huỳnh

06/11/2021, 3:04 AM

nope, this’s non-prod env

Mayank

06/11/2021, 3:05 AM

One possibility is that your servers don't have enough threads to handle the offline+realtime request.

Mayank

06/11/2021, 3:06 AM

can you send the query to just

RuleLogsUAT_OFFLINE

RuleLogsUAT_REALTIME

Neha Pawar

06/11/2021, 3:06 AM

can you add 2 servers and separate the offline and realtime? do you have too many segments on each server? and whats size of each segment?

Phúc Huỳnh

06/11/2021, 3:09 AM

Copy code

can you add 2 servers and separate the offline and realtime?

I don’t think it’s the problem

Copy code

do you have too many segments on each server? and whats size of each segment?

Its’s around 14 realtime segments & 8 offfline segments, size of each offline segments is around 400~700kb

Mayank

06/11/2021, 3:10 AM

select count(*) from RuleLogsUAT_OFFLINE

Mayank

06/11/2021, 3:11 AM

How many cores?

Phúc Huỳnh

06/11/2021, 3:12 AM

here’s the resources using

Mayank

06/11/2021, 3:12 AM

Is server-1 always the issue?

Phúc Huỳnh

06/11/2021, 3:13 AM

i think so

Phúc Huỳnh

06/11/2021, 3:13 AM

only server-1 has

Timed out while polling results block,

logging

Phúc Huỳnh

06/11/2021, 3:13 AM

Copy code

Timed out while polling results block, numBlocksMerged: 0 (query: QueryContext{_tableName='RuleLogsUAT_REALTIME', _selectExpressions=[count(*)], _aliasList=[null], _filter=null, _groupByExpressions=null, _havingFilter=null, _orderByExpressions=null, _limit=10, _offset=0, _queryOptions={responseFormat=sql, groupByMode=sql, timeoutMs=9999}, _debugOptions=null, _brokerRequest=BrokerRequest(querySource:QuerySource(tableName:RuleLogsUAT_REALTIME), pinotQuery:PinotQuery(dataSource:DataSource(tableName:RuleLogsUAT_REALTIME), selectList:[Expression(type:FUNCTION, functionCall:Function(operator:COUNT, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:*))]))], queryOptions:{responseFormat=sql, groupByMode=sql, timeoutMs=9999}))})

Phúc Huỳnh

06/11/2021, 3:13 AM

Copy code

Timed out while polling results block, numBlocksMerged: 0 (query: QueryContext{_tableName='RuleLogsUAT_OFFLINE', _selectExpressions=[count(*)], _aliasList=[null], _filter=null, _groupByExpressions=null, _havingFilter=null, _orderByExpressions=null, _limit=10, _offset=0, _queryOptions={responseFormat=sql, groupByMode=sql, timeoutMs=9999}, _debugOptions=null, _brokerRequest=BrokerRequest(querySource:QuerySource(tableName:RuleLogsUAT_OFFLINE), pinotQuery:PinotQuery(dataSource:DataSource(tableName:RuleLogsUAT_OFFLINE), selectList:[Expression(type:FUNCTION, functionCall:Function(operator:COUNT, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:*))]))], queryOptions:{responseFormat=sql, groupByMode=sql, timeoutMs=9999}))})

Phúc Huỳnh

06/11/2021, 3:13 AM

both query in realtime_server & offline_server

Mayank

06/11/2021, 3:14 AM

any errors/exceptions in server-1 log?

Mayank

06/11/2021, 3:14 AM

Clearly there's some issue there.

Phúc Huỳnh

06/11/2021, 3:16 AM

it’s weird, not all of query is timeout

Mayank

06/11/2021, 3:17 AM

What's the replication? If > 1, then queries that don't hit server-1 probably work.

Phúc Huỳnh

06/11/2021, 3:18 AM

replication = 2

Mayank

06/11/2021, 3:19 AM

yeah, so then not all queries may go to server-1 replica

Mayank

06/11/2021, 3:19 AM

also, what's the overall read qps to the cluster?

Mayank

06/11/2021, 3:19 AM

are you firing queries only manually, or is there more read qps coming from somewhere

Phúc Huỳnh

06/11/2021, 3:19 AM

only me using

Phúc Huỳnh

06/11/2021, 3:19 AM

so qps = 1

Mayank

06/11/2021, 3:20 AM

can you restart server-1?

Phúc Huỳnh

06/11/2021, 3:20 AM

okie

Mayank

06/11/2021, 3:21 AM

Something is wrong in that server, we will need to look at the logs and metrics (may be thread dump) to see what's happening in it.

Mayank

06/11/2021, 3:21 AM

perhaps take a threaddump before you restart?

Phúc Huỳnh

06/11/2021, 3:24 AM

well, the issue switch to server-2 when i restart server-1

Phúc Huỳnh

06/11/2021, 3:24 AM

Copy code

Timed out while polling results block, numBlocksMerged: 0 (query: QueryContext{_tableName='RuleLogsUAT_REALTIME', _selectExpressions=[*], _aliasList=[null], _filter=created_at_days_epoch > '18761', _groupByExpressions=null, _havingFilter=null, _orderByExpressions=null, _limit=10, _offset=0, _queryOptions={responseFormat=sql, groupByMode=sql, timeoutMs=9999}, _debugOptions=null, _brokerRequest=BrokerRequest(querySource:QuerySource(tableName:RuleLogsUAT_REALTIME), pinotQuery:PinotQuery(dataSource:DataSource(tableName:RuleLogsUAT_REALTIME), selectList:[Expression(type:IDENTIFIER, identifier:Identifier(name:*))], filterExpression:Expression(type:FUNCTION, functionCall:Function(operator:GREATER_THAN, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:created_at_days_epoch)), Expression(type:LITERAL, literal:<Literal stringValue:18761>)])), orderByList:[], limit:10, queryOptions:{responseFormat=sql, groupByMode=sql, timeoutMs=9999}))})

Mayank

06/11/2021, 3:26 AM

grep for "Driver, indexing time" in both server logs

Mayank

06/11/2021, 3:26 AM

Also paste broker log when query successful

Mayank

06/11/2021, 3:28 AM

Are you running master, or 0.7.1 release?

Phúc Huỳnh

06/11/2021, 3:44 AM

Here’s the logs server 1 & 2

Phúc Huỳnh

06/11/2021, 3:44 AM

Copy code

Are you running master, or 0.7.1 release?

I’m running on master

Mayank

06/11/2021, 3:44 AM

oh if master, then can you do a curl on the <server>:7500/appConfigs?

Phúc Huỳnh

06/11/2021, 3:46 AM

Copy code

# curl
curl: try 'curl --help' or 'curl --manual' for more information
# curl localhost:7500/appConfigs?
curl: (7) Failed to connect to localhost port 7500: Connection refused

I don’t think server expose port

Neha Pawar

06/11/2021, 8:18 PM

Copy code

Is server-1 always the issue?

btw, it was not just server1. your log which you shared initially, showed both server1 and server 2 failing across the 5 queries from the start. So it could very well be because of offline realtime sharing the server. Restart is not what it made it go to server2.

Phúc Huỳnh

06/12/2021, 3:44 AM

Yes, i not just server 1. I just reinstall all cluster, keep volume mount. But the issue happen agains

Phúc Huỳnh

06/12/2021, 3:48 AM

Copy code

Timed out while polling results block, numBlocksMerged: 0 (query: QueryContext{_tableName='RuleLogsUAT_OFFLINE', _selectExpressions=[count(*)], _aliasList=[null], _filter=created_at_days_epoch <= '18761', _groupByExpressions=null, _havingFilter=null, _orderByExpressions=null, _limit=10, _offset=0, _queryOptions={responseFormat=sql, groupByMode=sql, timeoutMs=9999}, _debugOptions=null, _brokerRequest=BrokerRequest(querySource:QuerySource(tableName:RuleLogsUAT_OFFLINE), pinotQuery:PinotQuery(dataSource:DataSource(tableName:RuleLogsUAT_OFFLINE), selectList:[Expression(type:FUNCTION, functionCall:Function(operator:COUNT, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:*))]))], filterExpression:Expression(type:FUNCTION, functionCall:Function(operator:LESS_THAN_OR_EQUAL, operands:[Expression(type:IDENTIFIER, identifier:Identifier(name:created_at_days_epoch)), Expression(type:LITERAL, literal:<Literal stringValue:18761>)])), queryOptions:{responseFormat=sql, groupByMode=sql, timeoutMs=9999}))})

now it’s happend on server-0 😞

2 Views

Open in Slack

Previous Next