Klay created HBASE-28545:
----------------------------
Summary: Worker thread gets stuck in an infinite retry when
TRUNCATE command runs into RowTooBigException
Key: HBASE-28545
URL: https://issues.apache.org/jira/browse/HBASE-28545
Project: HBase
Issue Type: Bug
Affects Versions: 2.5.8, 2.4.17
Reporter: Klay
Attachments: hbase-master.log
Hi, I am testing the reliability of HBase to see if it could work normally or
properly handle exceptions under certain different configurations.
When setting +hbase.table.max.rowsize+ to a relatively small size, create an
empty table and then truncate it could get worker thread to get stuck in an
infinite retry and generate massive logs.
h1. Reproduce
This bug can be reproduced determinstically with the following steps:
1. Set hbase.table.max.rowsize to a relatively small value: 745
hbase-site.xml
{code:java}
<property>
<name>hbase.table.max.rowsize</name>
<value>745</value>
</property>
{code}
2. Start up HBase cluster 2.5.8 (1HM, 2RS) and execute the following commands
from hbase shell
{code:java}
create 'uuid0f06811e5d11431fa9d4a543705b8747', {NAME =>
'uuidad7c09870a6346598bbca56cb97c4c67', VERSIONS => 4, COMPRESSION => 'GZ',
BLOOMFILTER => 'NONE', IN_MEMORY => 'false'}, {NAME =>
'uuidd2c5ad4df7b844afb4c2ac92b224dedd', VERSIONS => 4, COMPRESSION => 'NONE',
BLOOMFILTER => 'NONE', IN_MEMORY => 'true'}, {NAME =>
'uuid6e21f5f492eb4b9ba0e431b9a0666dae', VERSIONS => 4, COMPRESSION => 'NONE',
BLOOMFILTER => 'NONE', IN_MEMORY => 'true'}, {NAME =>
'uuidfb110629fba44915956e41609b68ebe9', VERSIONS => 2, COMPRESSION => 'NONE',
BLOOMFILTER => 'ROW', IN_MEMORY => 'false'}, {NAME =>
'uuid4943640bf1f6425582ac9b3572d95964', VERSIONS => 4, COMPRESSION => 'GZ',
BLOOMFILTER => 'ROWCOL', IN_MEMORY => 'false'}
truncate 'uuid0f06811e5d11431fa9d4a543705b8747' {code}
*truncate* command timeout after 10m. However, the PEWorker thread still gets
stuck in an *infinite retry* and keep generating a massive WARN in HMaster logs
{code:java}
➜ log git:(main) ✗ ls
hbase--master-09e0b9e25e7c.log hbase--master-09e0b9e25e7c.log.12
hbase--master-09e0b9e25e7c.log.16 hbase--master-09e0b9e25e7c.log.2
hbase--master-09e0b9e25e7c.log.5 hbase--master-09e0b9e25e7c.log.9
SecurityAuth.audit
hbase--master-09e0b9e25e7c.log.1 hbase--master-09e0b9e25e7c.log.13
hbase--master-09e0b9e25e7c.log.17 hbase--master-09e0b9e25e7c.log.20
hbase--master-09e0b9e25e7c.log.6 hbase--master-09e0b9e25e7c.out
hbase--master-09e0b9e25e7c.log.10 hbase--master-09e0b9e25e7c.log.14
hbase--master-09e0b9e25e7c.log.18 hbase--master-09e0b9e25e7c.log.3
hbase--master-09e0b9e25e7c.log.7 hbase--zookeeper-09e0b9e25e7c.log
hbase--master-09e0b9e25e7c.log.11 hbase--master-09e0b9e25e7c.log.15
hbase--master-09e0b9e25e7c.log.19 hbase--master-09e0b9e25e7c.log.4
hbase--master-09e0b9e25e7c.log.8 hbase--zookeeper-09e0b9e25e7c.out {code}
The logs contain the following exceptions
{code:java}
2024-04-23T02:52:16,144 WARN [PEWorker-14] procedure.TruncateTableProcedure:
Retriable error trying to truncate table=uuid0f06811e5d11431fa9d4a543705b8747
state=TRUNCATE_TABLE_CLEAR_FS_LAYOUT
org.apache.hadoop.hbase.regionserver.RowTooBigException:
org.apache.hadoop.hbase.regionserver.RowTooBigException: Max row size allowed:
745, but the row is bigger than that, the row info:
uuid0f06811e5d11431fa9d4a543705b8747,,1713840709844.c03450373b32cba95a2dd3139f0a2201./info:state/1713840716052/Put/vlen=6/seqid=16,
already have process row cells = 6, it belong to region =
hbase:meta,,1.1588230740
at
org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:653)
at
org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:145)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.populateResult(RegionScannerImpl.java:342)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.nextInternal(RegionScannerImpl.java:513)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.nextRaw(RegionScannerImpl.java:278)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.next(RegionScannerImpl.java:256)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.next(RegionScannerImpl.java:243)
at
org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2654)
at
org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2577)
at
org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:45002)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:415)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124)
at org.apache.hadoop.hbase.ipc.RpcHandler.run(RpcHandler.java:102)
at org.apache.hadoop.hbase.ipc.RpcHandler.run(RpcHandler.java:82)
at sun.reflect.GeneratedConstructorAccessor30.newInstance(Unknown Source)
~[?:?]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
~[?:1.8.0_362]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
~[?:1.8.0_362]
at
org.apache.hadoop.hbase.ipc.RemoteWithExtrasException.instantiateException(RemoteWithExtrasException.java:110)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.RemoteWithExtrasException.unwrapRemoteException(RemoteWithExtrasException.java:100)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.protobuf.ProtobufUtil.makeIOExceptionOfException(ProtobufUtil.java:280)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.protobuf.ProtobufUtil.handleRemoteException(ProtobufUtil.java:265)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.client.RegionServerCallable.call(RegionServerCallable.java:126)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:103)
~[hbase-client-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.client.HTable.get(HTable.java:390)
~[hbase-client-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.client.HTable.lambda$get$0(HTable.java:363)
~[hbase-client-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.trace.TraceUtil.trace(TraceUtil.java:216)
~[hbase-common-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.client.HTable.get(HTable.java:363)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.MetaTableAccessor.get(MetaTableAccessor.java:248)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.MetaTableAccessor.getRegionResult(MetaTableAccessor.java:344)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.MetaTableAccessor.getMergeRegions(MetaTableAccessor.java:374)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.master.procedure.DeleteTableProcedure.deleteFromFs(DeleteTableProcedure.java:283)
~[hbase-server-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.master.procedure.TruncateTableProcedure.executeFromState(TruncateTableProcedure.java:103)
~[hbase-server-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.master.procedure.TruncateTableProcedure.executeFromState(TruncateTableProcedure.java:44)
~[hbase-server-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.StateMachineProcedure.execute(StateMachineProcedure.java:188)
~[hbase-procedure-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.Procedure.doExecute(Procedure.java:942)
~[hbase-procedure-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.execProcedure(ProcedureExecutor.java:1765)
~[hbase-procedure-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1443)
~[hbase-procedure-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$1000(ProcedureExecutor.java:77)
~[hbase-procedure-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.runProcedure(ProcedureExecutor.java:2091)
~[hbase-procedure-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.trace.TraceUtil.trace(TraceUtil.java:216)
~[hbase-common-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:2118)
~[hbase-procedure-2.5.8.jar:2.5.8]
Caused by: org.apache.hadoop.hbase.ipc.RemoteWithExtrasException:
org.apache.hadoop.hbase.regionserver.RowTooBigException: Max row size allowed:
745, but the row is bigger than that, the row info:
uuid0f06811e5d11431fa9d4a543705b8747,,1713840709844.c03450373b32cba95a2dd3139f0a2201./info:state/1713840716052/Put/vlen=6/seqid=16,
already have process row cells = 6, it belong to region =
hbase:meta,,1.1588230740
at
org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:653)
at
org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:145)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.populateResult(RegionScannerImpl.java:342)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.nextInternal(RegionScannerImpl.java:513)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.nextRaw(RegionScannerImpl.java:278)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.next(RegionScannerImpl.java:256)
at
org.apache.hadoop.hbase.regionserver.RegionScannerImpl.next(RegionScannerImpl.java:243)
at
org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2654)
at
org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2577)
at
org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:45002)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:415)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:124)
at org.apache.hadoop.hbase.ipc.RpcHandler.run(RpcHandler.java:102)
at org.apache.hadoop.hbase.ipc.RpcHandler.run(RpcHandler.java:82)
at
org.apache.hadoop.hbase.ipc.AbstractRpcClient.onCallFinished(AbstractRpcClient.java:388)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.AbstractRpcClient.access$100(AbstractRpcClient.java:92)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:425)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.AbstractRpcClient$3.run(AbstractRpcClient.java:420)
~[hbase-client-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.ipc.Call.callComplete(Call.java:114)
~[hbase-client-2.5.8.jar:2.5.8]
at org.apache.hadoop.hbase.ipc.Call.setException(Call.java:129)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.NettyRpcDuplexHandler.readResponse(NettyRpcDuplexHandler.java:199)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hadoop.hbase.ipc.NettyRpcDuplexHandler.channelRead(NettyRpcDuplexHandler.java:220)
~[hbase-client-2.5.8.jar:2.5.8]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
~[hbase-shaded-netty-4.1.5.jar:?]
at
org.apache.hbase.thirdparty.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
~[hbase-shaded-netty-4.1.5.jar:?]
at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_362]
{code}
I have attached the one example hmaster log.
h1. Root Cause
If decrease the length of the table name and cf name in the create table
command, the truncate will work normally. This indicates that the symptom could
be triggered as long as there's a table whose metadata size is larger than the
max row size.
E.g., using the default max row size value (1GB), if create a table with a
large metadata size (lots of columns with long names), it might still cause the
similar infinite loop problem.
This usually won't happen with the default configurations. However, users are
more likely to run into this exception if they set the max row size to a
smaller value and create a large table.
h1. Fix
A better error handler might work
* This infinite loop could be avoided by adding a retry limit if the truncate
command keeps running into RowTooBigException.
I am still examining the exact root cause. I could try to provide a patch. Any
suggestions are welcome. Thank you.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
