[HADOOP-15840] Slow RPC logger too spammy

• Type: Improvement
• Status: Open
• Priority: Minor
• Resolution: Unresolved
• Affects Version/s: 2.8.0, 2.7.4, 3.0.0-alpha1
• Assignee: Unassigned
• Reporter: Wei-Chiu Chuang
• Created: 10/Oct/18 16:10
• Updated: 02/Oct/19 17:15

Description

HADOOP-12325 added a capability where "slow" RPCs are logged in NN log when ipc.server.log.slow.rpc is enabled.

The "slow" RPCs are supposed to be those whose processing time is outside 3 standard deviation, and it supposed to account for 0.3% of total RPCs.

However, I found in practice, NN marks more than 1% of total RPCs as slow, and I've seen RPCs whose processing time is 1ms declared slow too.

2018-10-08 01:48:33,203 WARN org.apache.hadoop.ipc.Server: Slow RPC : sendHeartbeat took 1 milliseconds to process from client 10.17.199.16:56645
2018-10-08 01:48:33,219 WARN org.apache.hadoop.ipc.Server: Slow RPC : sendHeartbeat took 1 milliseconds to process from client 10.17.190.44:36435
2018-10-08 01:48:33,308 WARN org.apache.hadoop.ipc.Server: Slow RPC : sendHeartbeat took 1 milliseconds to process from client 10.17.190.43:56530

This is too many. 1% means NN spits hundreds slow RPCs per second on average in NN log.

How about:

1. use 4 stddev?
2. use microsecond precision. Majority of RPCs takes less than 1 millisecond anyway. It makes the stddev calculation imprecise. An RPC could be calculated to spend 1 millisecond and be marked as "slow", since it starts from one millisecond and ends in the next millisecond.

 

anu any thoughts?

Issue Links

• relates to: HADOOP-12325 RPC Metrics : Add the ability track and log slow RPCs