Hey folks, we often see issues where the broker reports a server timed out

requestId=1450012346000019565,table=tablename,timeMs=16017,docs=30/685750,entries=0/390,segments(queried/processed/matched/consumingQueried/consumingProcessed/consumingMatched/unavailable):45/3/3/1/0/0/0,consumingFreshnessTimeMs=1696386119591,servers=3/4,groupLimitReached=false,brokerReduceTimeMs=0,exceptions=1,serverStats=(Server=SubmitDelayMs,ResponseDelayMs,ResponseSize,DeserializationTimeMs,RequestSentDelayMs);server-p8s_R=0,8,12885,0,0;server-pca_R=0,11,13199,0,0;server-q23_R=0,-1,0,0,755;server-ucq_R=0,12,17031,0,0,offlineThreadCpuTimeNs(total/thread/sysActivity/resSer):0/0/0/0,realtimeThreadCpuTimeNs(total/thread/sysActivity/resSer):0/0/0/0,clientIp=unknown,query=select * from tablename limit 10

But the server logs for

server-q23_R

show the response should have been very quick

Processed requestId=1450012346000019565,table=logging_adhocstore_herb_REALTIME,segments(queried/processed/matched/consumingQueried/consumingProcessed/consumingMatched/invalid/limit/value)=18/1/1/1/0/0/0/17/0,schedulerWaitMs=0,reqDeserMs=0,totalExecMs=7,resSerMs=1,totalTimeMs=8,minConsumingFreshnessMs=1696405334405,broker=Broker_7e343be1-1643-47de-9927-3ffa95804a11,numDocsScanned=10,scanInFilter=0,scanPostFilter=130,sched=FCFS,threadCpuTimeNs(total/thread/sysActivity/resSer)=0/0/0/0

Any tips on debugging this issue? We’ve seen this self resolve in a few minutes, but also not resolve over multiple days. It doesn’t happen on every request, but happens consistently to ~25% of queries, 50% of queries to this server (rf=2). Restarting the server resolves the issue

Hmm, this is interesting. Normally, I’d suspect the query is sitting in servers’ queue. But from your log it seems that is not the case (schedulerWaitMs=0). Can you share the timestamps? cc: @Jackie

server:

2023-10-04T07:42:14.948+00:00

broker:

2023-10-04T07:42:30.203+00:00

I had started to take a look at the code about a month ago when I first started seeing this. It seems the

requestId=…

line is logged before the response is sent, maybe some exception is preventing it from being sent? But I couldn’t find any relevant logs from InstanceRequestHandler

Are you running on k8s? cc: @saurabh dubey

RequestSentDelayMs is the time b/w starting to write the request to the netty channel b/w broker and server. In this case, it's 755ms for the server in question

it’s not k8s, but it is docker container based w/ some in house orchestration framework The server resource usage/GC is very low during this. I will need get back to you on if it’s a single/multiple brokers

Also will help to check if you're seeing any network packet drops etc

No packet drops from our metrics either, but no metrics around packets queued. generally the system level metrics I could find looked healthy

packet retransmissions looks interesting. Any spikes in that around this time?

hmm, yes! the spike correlates

I see. retransmissions is generally due to packet drops (no ACK etc) -> causing the sender to retransmit the packet. I wonder if this might be the reason

Sometime early Jan this year

Will it be possible to investigate the reason for TCP retransmissions?

I’ll follow up internally and get back, thank you for all the help so far

Hey @Chris Peck is the packet retransmit an internal metric?

i’m actually not sure what the exact source of the metric is - yet

Thanks @Chris Peck do keep us posted 🙂

FYI: @Prashant Pandey

A bit more info, for the attached graph of server retransmits: 1. All spikes above ~2 retransmit/s can be correlated to broker show timeout/server shows completed. 2. The prolonged spike around 7:40 is due to a node replacement, maybe indicating this is some form of resource scarcity? We usually have 2 brokers, during our replacement process one is killed and a replacement is brought up w/ the old broker’s helix id. During this time there’s only one broker and it’s visible in this server metric

Are there any network bandwidth related metrics / throttling limits that you're aware of? If these are some cloud provider's VMs, maybe they have some metrics / limits details? I'm thinking if it's either due to some sort of bandwidth throttling / flooding of tcp packets causing some packets getting queued somewhere (not a networking expert by any means)