[HBASE-16972] Log more details for Scan#next request when responseTooSlow

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.1.7, 1.2.4
• Fix Version/s: 1.3.0, 1.2.5, 1.1.8, 2.0.0
• Component/s: Operability
• Hadoop Flags: Incompatible change, Reviewed
• Assignee: Yu Li
• Reporter: Yu Li
• Created: 31/Oct/16 04:00
• Updated: 09/Nov/17 02:47
• Resolved: 06/Nov/16 08:52

Description

Currently for if responseTooSlow happens on the scan.next call, we will get warn log like below:

2016-10-31 11:43:23,430 WARN  [RpcServer.FifoWFPBQ.priority.handler=5,queue=1,port=60193] ipc.RpcServer(2574):
(responseTooSlow): {"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)",
"starttimems":1477885403428,"responsesize":52,"method":"Scan","param":"scanner_id: 11 number_of_rows: 2147483647
close_scanner: false next_call_seq: 0 client_handles_partials: true client_handles_heartbeats: true
track_scan_metrics: false renew: false","processingtimems":2,"client":"127.0.0.1:60254","queuetimems":0,"class":"HMaster"}

From which we only have a scanner_id and impossible to know what exactly this scan is about, like against which region of which table.

After this JIRA, we will improve the message to something like below (notice the last line):

2016-10-31 11:43:23,430 WARN  [RpcServer.FifoWFPBQ.priority.handler=5,queue=1,port=60193] ipc.RpcServer(2574):
(responseTooSlow): {"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)",
"starttimems":1477885403428,"responsesize":52,"method":"Scan","param":"scanner_id: 11 number_of_rows: 2147483647
close_scanner: false next_call_seq: 0 client_handles_partials: true client_handles_heartbeats: true
track_scan_metrics: false renew: false","processingtimems":2,"client":"127.0.0.1:60254","queuetimems":0,"class":"HMaster",
"scandetails":"table: hbase:meta region: hbase:meta,,1.1588230740"}

Issue Links

• relates to: HBASE-17011 backport HBASE-16972 to 1.3.1