Xiao Liu created HBASE-29777:
--------------------------------
Summary: Slow and Large Response RPC StartTime in SlowLog
Operation Details page is incorrect
Key: HBASE-29777
URL: https://issues.apache.org/jira/browse/HBASE-29777
Project: HBase
Issue Type: Bug
Affects Versions: 2.5.13, 2.6.4, 3.0.0-beta-1
Reporter: Xiao Liu
Assignee: Xiao Liu
Fix For: 2.7.0, 3.0.0-beta-2, 2.6.5, 2.5.14
Attachments: large.png, slow.png
When the slowlog feature is enabled, we observe a discrepancy between the start
times displayed for SlowRPC and Large Response RPC on the RegionServer UI page
and the actual times.
We can pull the latest code and compile it, then add the following
configuration, and start the cluster, maybe after a scan meta table operation,
then we can see that there's a discrepancy between the start time in the log
and the displayed time, which feels quite odd.
{code:xml}
<property>
<name>hbase.regionserver.slowlog.systable.enabled</name>
<value>true</value>
</property>
<property>
<name>hbase.regionserver.slowlog.buffer.enabled</name>
<value>true</value>
</property>
<property>
<name>hbase.ipc.warn.response.time</name>
<value>1</value>
</property>
<property>
<name>hbase.ipc.warn.response.size</name>
<value>1</value>
</property>
{code}
{code:java}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=6,queue=4,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223468","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":3,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":0,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=11,queue=2,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223469","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":2,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":1,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=5,queue=3,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223469","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":2,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":1,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=16,queue=7,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223468","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":3,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":0,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=4,queue=2,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223468","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":3,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":0,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=12,queue=3,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223469","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":2,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":0,"class":"HRegionServer"}
2025-12-15T00:03:43,472 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=13,queue=4,port=16020] ipc.RpcServer:
(responseTooLarge & TooSlow):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223468","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":3,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":0,"class":"HRegionServer"}
2025-12-15T00:03:43,473 WARN
[RpcServer.priority.RWQ.Fifo.read.handler=6,queue=4,port=16020] ipc.RpcServer:
(responseTooLarge):
{"call":"Scan(org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ScanRequest)","starttimems":"1765728223473","responsesize":"935","method":"Scan","param":"region
{ type: REGION_NAME value: \"hbase:meta,,1\" } scan { column { family:
\"info\" } attribute { name: \"_isolationlevel_\" value: \"\\000\" } start_row:
\"
<TRUNCATED>","processingtimems":0,"blockbytesscanned":"4136","fsreadtime":"0","client":"192.168.1.44:57802","queuetimems":5,"class":"HRegionServer"}
2025-12-15T00:03:43,491 INFO
[RpcServer.default.FPBQ.Fifo.handler=29,queue=2,port=16020]
regionserver.HRegion: writing data to region
hbase:slowlog,,1765727627468.64ed28e9c8e5a433df1d54662ff9e06f. with WAL
disabled. Data may be lost in the event of a crash.
{code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
