[
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 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}
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.
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.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, 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}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
