[
https://issues.apache.org/jira/browse/HBASE-29777?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Xiao Liu updated HBASE-29777:
-----------------------------
Description:
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, which has a 30min gap.
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}
was:
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, which is a 30min gap.
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}
> 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: 3.0.0-beta-1, 2.6.4, 2.5.13
> Reporter: Xiao Liu
> Assignee: Xiao Liu
> Priority: Major
> Labels: pull-request-available
> Fix For: 2.7.0, 3.0.0-beta-2, 2.6.4, 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, which has a 30min gap.
> 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)
