[HBASE-22935] TaskMonitor warns MonitoredRPCHandler task may be stuck when it recently started

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 3.0.0-alpha-1, 1.4.0, 1.5.0, 1.3.3, 2.0.0
• Fix Version/s: 3.0.0-alpha-1, 1.5.0, 2.3.0, 2.2.1, 1.3.6, 1.4.11, 2.1.7
• Component/s: logging
• Hadoop Flags: Reviewed
• Assignee: David Manning
• Reporter: David Manning
• Created: 27/Aug/19 23:42
• Updated: 02/Oct/19 11:59
• Resolved: 28/Aug/19 18:35

Description

After setting hbase.taskmonitor.rpc.warn.time to 180000, the logs show WARN messages such as these

2019-08-08 21:50:02,601 WARN  [read for TaskMonitor] monitoring.TaskMonitor - Task may be stuck: RpcServer.FifoWFPBQ.default.handler=4,queue=4,port=60020: status=Servicing call from <ip>:55164: Scan, state=RUNNING, startTime=1563305858103, completionTime=-1, queuetimems=1565301002599, starttimems=1565301002599, clientaddress=<ip>, remoteport=55164, packetlength=370, rpcMethod=Scan

Notice that the first starttimems is far in the past. The second starttimems and the queuetimems are much closer to the log timestamp than 180 seconds. I think this is because the warnTime is initialized to the time that MonitoredTaskImpl is created, but never updated until we write a warn message to the log.

Issue Links

• is related to: HBASE-18248 Warn if monitored RPC task has been tied up beyond a configurable threshold
• links to: Review Board (master)