[HBASE-21179] Fix the number of actions in responseTooSlow log

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 3.0.0-alpha-1, 1.3.3, 1.2.8, 2.2.0, 1.4.8, 2.1.1, 2.0.3
• Component/s: logging, rpc
• Assignee: Guangxu Cheng
• Reporter: Guangxu Cheng
• Created: 10/Sep/18 12:29
• Updated: 01/Feb/19 20:12
• Resolved: 13/Sep/18 07:18

Description

responseTooSlow

2018-09-10 16:13:53,022 WARN [B.DefaultRpcServer.handler=209,queue=29,port=60020] ipc.RpcServer: (responseTooSlow): {"processingtimems":321262,"call":"Multi(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$MultiRequest)","client":"127.0.0.1:56149","param":"region= tsdb,\\x00\\x00.[\\x89\\x1F\\xB0\\x00\\x00\\x01\\x00\\x01Y\\x00\\x00\\x02\\x00\\x00
x04,1536133210446.7c752de470bd5558a001117b123a5db5., for 1 actions and 1st row key=\\x00\\x00.[\\x96
x16p","starttimems":1536566911759,"queuetimems":0,"class":"HRegionServer","responsesize":2,"method":"Multi"}

The responseTooSlow log is printed when the processing time of a request exceeds the specified threshold. The number of actions and the contents of the first rowkey in the request will be included in the log.
However, the number of actions is inaccurate, and it is actually the number of regions that the request needs to visit.
Just like the logs above, users may be mistaken for using 321262ms to process an action, which is incredible, so we need to fix it.