[jira] [Created] (HBASE-17213) Add responseTooSlow logging for calls with long totalCallTime

["Yu Li (JIRA)" <ji...@apache.org>]

Yu Li created HBASE-17213:
-----------------------------

             Summary: Add responseTooSlow logging for calls with long totalCallTime
                 Key: HBASE-17213
                 URL: https://issues.apache.org/jira/browse/HBASE-17213
             Project: HBase
          Issue Type: Improvement
            Reporter: Yu Li
            Assignee: Yu Li


Now we only have responseTooSlow logging for long processCallTime, it makes sense not to log for long queueCallTime since a long processCallTime will cause long queueCallTime for all succeeding request in queue. However, in our product environment we ever observed the case that both processCallTime and queueCallTime didn't reach the 10s threshold but totalCallTime did, but have no idea what the call is against.

Here we propose to add some responseTooSlow logging for totalCallTime of the above case, but with some logging rate limit to avoid slow processCallTime under heavy load (in which case call queue might be full and many calls queued thus plenty of long queueCallTime) introduce too many such logs.

To be explicit, after patch there will be some new log like:
{noformat}
2016-07-27 11:01:12,130 WARN  [PriorityRpcServer.handler=4,queue=0,port=61961] ipc.RpcServer(681):
(responseTooSlow-LongCallTime):  {"processingtimems":5,"call":"Scan(org.apache.hadoop.hbase.protobuf
.generated.ClientProtos$ScanRequest)","client":"127.0.0.1:62002","param":"region { type: REGION_NAME
value: \"hbase:meta,,1\" } scan { start_row: \"hbase:namespace,default,99999999999999\" max_versions: 1
cache_blocks: true small: true reversed: true caching: 1 } number_of_rows: 1 close_scanner: true
client_handles_partials: true client_handles_heartbeats: true","starttimems":1469588472124,"queuetimems":1
,"class":"MiniHBaseClusterRegionServer","responsesize":12,"method":"Scan"}
{noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)