You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@phoenix.apache.org by Takashi Sasaki <ts...@gmail.com> on 2017/07/05 05:24:01 UTC
Exception ERROR 201 (22000): Illegal data. Expected length of at
least 8 bytes, but had 4
Hi,
I'm using Phoenix4.9.0/HBase1.3.0 with Spark2.1.1 on AWS EMR 5.6.0.
When one side uses Spark Streaming to write a lot of data and the
other side uses Spark to read data,
I encounter several similar exceptions.
17/07/05 04:33:47 ERROR Executor: Exception in task 83.0 in stage
166.0 (TID 95211)
org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: java.sql.SQLException: ERROR 201
(22000): Illegal data. ERROR 201 (22000): ERROR 201 (22000): Illegal
data. Expected length of at least 8 bytes, but had 4
TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
### The error may exist in agp/mapper/TripMapper.java (best guess)
### The error may involve agp.mapper.TripMapper.selectLast
### The error occurred while handling results
### SQL: SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
DESC NULLS LAST FETCH FIRST 1 ROW ONLY
### Cause: java.sql.SQLException: ERROR 201 (22000): Illegal data.
ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
at least 8 bytes, but had 4
TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:150)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy38.selectLast(Unknown Source)
at agp.dao.TripDAO.selectLast(TripDAO.java:55)
at agp.trip.func.trip.SelectTripCondition.fixAccOnLocation(SelectTripCondition.java:128)
at agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:65)
at agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:25)
at org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
at org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:434)
at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:440)
at scala.collection.Iterator$$anon$13.hasNext(Iterator.scala:461)
at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408)
at org.apache.spark.shuffle.sort.UnsafeShuffleWriter.write(UnsafeShuffleWriter.java:166)
at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:96)
at org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:53)
at org.apache.spark.scheduler.Task.run(Task.scala:99)
at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:322)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
at least 8 bytes, but had 4
TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
at org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
at org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
at org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
at org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
at org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:755)
at org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:699)
at org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(MergeSortResultIterator.java:72)
at org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(MergeSortResultIterator.java:93)
at org.apache.phoenix.iterate.MergeSortResultIterator.next(MergeSortResultIterator.java:58)
at org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(MergeSortTopNResultIterator.java:95)
at org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:68)
at com.sun.proxy.$Proxy37.next(Unknown Source)
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:345)
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:322)
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:295)
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:192)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
... 23 more
Caused by: org.apache.hadoop.hbase.DoNotRetryIOException:
org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 201 (22000):
ERROR 201 (22000): Illegal data. Expected length of at least 8 bytes,
but had 4 TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
at org.apache.phoenix.util.ServerUtil.createIOException(ServerUtil.java:81)
at org.apache.phoenix.util.ServerUtil.throwIOException(ServerUtil.java:55)
at org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:328)
at org.apache.phoenix.coprocessor.ScanRegionObserver.doPostScannerOpen(ScanRegionObserver.java:241)
at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.overrideDelegate(BaseScannerRegionObserver.java:215)
at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.nextRaw(BaseScannerRegionObserver.java:260)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2633)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2837)
at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34950)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
Expected length of at least 8 bytes, but had 4
at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
at org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
at org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
at org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
at org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
at org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:61)
at org.apache.phoenix.iterate.OrderedResultIterator.getResultIterator(OrderedResultIterator.java:254)
at org.apache.phoenix.iterate.OrderedResultIterator.next(OrderedResultIterator.java:198)
at org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:323)
... 10 more
Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
Expected length of at least 8 bytes, but had 4
at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
at org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
at org.apache.phoenix.schema.KeyValueSchema.next(KeyValueSchema.java:213)
at org.apache.phoenix.expression.ProjectedColumnExpression.evaluate(ProjectedColumnExpression.java:115)
at org.apache.phoenix.schema.KeyValueSchema.toBytes(KeyValueSchema.java:112)
at org.apache.phoenix.execute.TupleProjector.projectResults(TupleProjector.java:245)
at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$1.nextRaw(BaseScannerRegionObserver.java:441)
at org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:50)
... 13 more
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(RemoteExceptionHandler.java:97)
at org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:272)
at org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:64)
at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithoutRetries(RpcRetryingCaller.java:200)
at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:360)
at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:334)
at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:126)
at org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture.run(ResultBoundedCompletionService.java:65)
... 3 more
HBase Region Server Logs below,
1.
2017-07-05 04:33:41,181 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
2017-07-05 04:33:50,929 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
2.
2017-07-05 04:32:52,087 INFO [sync.2] wal.FSHLog: Slow sync cost: 104
ms, current pipeline:
[DatanodeInfoWithStorage[172.31.10.147:50010,DS-289c3237-9ec2-4abc-9fe8-e114fde75483,DISK],
DatanodeInfoWithStorage[172.31.8.18:50010,DS-5887519a-6424-4bf9-9c09-35d9b13b5b1d,DISK],
DatanodeInfoWithStorage[172.31.10.188:50010,DS-0c7f1e59-1719-4f5d-a400-79276b4469d1,DISK]]
2017-07-05 04:34:31,791 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
3.
2017-07-05 04:32:54,447 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.87 MB, cacheSize=1.87 MB, accesses=802,
hits=261, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=32.54%,
cachingAccesses=372, cachingHits=196, cachingHitsRatio=52.69%,
evictions=0, evicted=65, evictedPerRun=Infinity
2017-07-05 04:34:18,621 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
4.
2017-07-05 04:33:41,653 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
2017-07-05 04:33:50,601 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
5.
2017-07-05 04:32:04,566 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.82 MB, cacheSize=1.85 MB, accesses=300,
hits=114, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=38.00%,
cachingAccesses=203, cachingHits=114, cachingHitsRatio=56.16%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:33:41,167 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
6.
2017-07-05 04:31:52,910 INFO
[ip-172-31-11-39.ap-northeast-1.compute.internal,16020,1499227300627-index-writer--pool30-t13]
regionserver.HRegion: writing data to region
TRB,\x0C\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.f0fade12881d6c99e9674639c90acad1.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
GB, blockCount=2, accesses=49007, hits=49007, hitRatio=100.00%, ,
cachingAccesses=49007, cachingHits=49007, cachingHitsRatio=100.00%,
evictions=179, evicted=0, evictedPerRun=0.0
2017-07-05 04:32:04,581 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=79.99 GB, usedSize=5.59 MB, cacheSize=3.66 MB, accesses=599,
hits=218, IOhitsPerSecond=0, IOTimePerHit=0.09, hitRatio=36.39%,
cachingAccesses=402, cachingHits=218, cachingHitsRatio=54.23%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:33:46,020 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
7.
2017-07-05 04:31:53,027 INFO
[ip-172-31-12-156.ap-northeast-1.compute.internal,16020,1499227465864-index-writer--pool26-t15]
regionserver.HRegion: writing data to region
TRB,\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.31b5cfcc09891813241932c46e2e6d5b.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:34:10,233 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
2017-07-05 04:34:29,590 INFO [LruBlockCacheStatsExecutor]
hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
GB, blockCount=2, accesses=27170, hits=27170, hitRatio=100.00%, ,
cachingAccesses=27170, cachingHits=27170, cachingHitsRatio=100.00%,
evictions=179, evicted=0, evictedPerRun=0.0
2017-07-05 04:34:29,643 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.90 MB, cacheSize=1.90 MB, accesses=295,
hits=98, IOhitsPerSecond=0, IOTimePerHit=NaN, hitRatio=33.22%,
cachingAccesses=200, cachingHits=98, cachingHitsRatio=49.00%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:35:13,274 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
8.
2017-07-05 04:27:41,202 ERROR
[RpcServer.FifoWFPBQ.default.handler=29,queue=2,port=16020]
coprocessor.MetaDataEndpointImpl: getTable failed
org.apache.hadoop.hbase.NotServingRegionException:
SYSTEM.CATALOG,,1499216017494.3bbe2fb5b186285a9555b45c87684cc7. is
closing
at org.apache.hadoop.hbase.regionserver.HRegion.startRegionOperation(HRegion.java:8291)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2645)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2640)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2634)
at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.buildTable(MetaDataEndpointImpl.java:533)
at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2939)
at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2884)
at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.getTable(MetaDataEndpointImpl.java:492)
at org.apache.phoenix.coprocessor.generated.MetaDataProtos$MetaDataService.callMethod(MetaDataProtos.java:16267)
at org.apache.hadoop.hbase.regionserver.HRegion.execService(HRegion.java:8095)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnRegion(RSRpcServices.java:2072)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.execService(RSRpcServices.java:2054)
at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34954)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
2017-07-05 04:31:53,017 INFO
[ip-172-31-14-56.ap-northeast-1.compute.internal,16020,1499227310987-index-writer--pool43-t18]
regionserver.HRegion: writing data to region
TRB,\x07\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.c93f2a12e912e9501f0801e9cb73f75c.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:32:04,571 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=3.01 MB, cacheSize=1.97 MB, accesses=1077,
hits=881, IOhitsPerSecond=0, IOTimePerHit=0.16, hitRatio=81.80%,
cachingAccesses=980, cachingHits=881, cachingHitsRatio=89.90%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:36:34,114 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
9.
2017-07-05 04:31:52,915 INFO
[ip-172-31-3-154.ap-northeast-1.compute.internal,16020,1499227309930-index-writer--pool3-t13]
regionserver.HRegion: writing data to region
TRB,\x0D\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.9eca4d9d19a712533aa240853173c816.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:32:04,506 INFO [LruBlockCacheStatsExecutor]
hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
GB, blockCount=4, accesses=26651, hits=26651, hitRatio=100.00%, ,
cachingAccesses=26651, cachingHits=26651, cachingHitsRatio=100.00%,
evictions=179, evicted=0, evictedPerRun=0.0
2017-07-05 04:32:04,556 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.85 MB, cacheSize=1.85 MB, accesses=334,
hits=134, IOhitsPerSecond=0, IOTimePerHit=0.15, hitRatio=40.12%,
cachingAccesses=239, cachingHits=134, cachingHitsRatio=56.07%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:33:33,010 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
2017-07-05 04:33:40,823 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
10.
2017-07-05 04:31:53,653 INFO
[ip-172-31-7-66.ap-northeast-1.compute.internal,16020,1499227313375-index-writer--pool38-t18]
regionserver.HRegion: writing data to region
TRP,\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.6706144c5be72f993a69ad9ad63005e5.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
GB, blockCount=1, accesses=24493, hits=24493, hitRatio=100.00%, ,
cachingAccesses=24493, cachingHits=24493, cachingHitsRatio=100.00%,
evictions=179, evicted=0, evictedPerRun=0.0
2017-07-05 04:32:04,577 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.48 MB, cacheSize=1.62 MB, accesses=260,
hits=81, IOhitsPerSecond=0, IOTimePerHit=0.10, hitRatio=31.15%,
cachingAccesses=164, cachingHits=81, cachingHitsRatio=49.39%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:36:04,834 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
11.
2017-07-05 04:31:53,327 INFO
[ip-172-31-8-18.ap-northeast-1.compute.internal,16020,1499227319500-index-writer--pool26-t18]
regionserver.HRegion: writing data to region
TRP,\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.53d87d4772b4e637b4dfd426bb11d624.
with WAL disabled. Data may be lost in the event of a crash.
2017-07-05 04:32:04,505 INFO [LruBlockCacheStatsExecutor]
hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
GB, blockCount=1, accesses=23309, hits=23309, hitRatio=100.00%, ,
cachingAccesses=23309, cachingHits=23309, cachingHitsRatio=100.00%,
evictions=179, evicted=0, evictedPerRun=0.0
2017-07-05 04:32:04,574 INFO [BucketCacheStatsExecutor]
bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
freeSize=80.00 GB, usedSize=2.83 MB, cacheSize=1.85 MB, accesses=330,
hits=138, IOhitsPerSecond=0, IOTimePerHit=0.12, hitRatio=41.82%,
cachingAccesses=232, cachingHits=138, cachingHitsRatio=59.48%,
evictions=0, evicted=0, evictedPerRun=NaN
2017-07-05 04:33:58,658 WARN [Finalizer] memory.GlobalMemoryManager:
Orphaned chunk of 104 bytes found during finalize
The TRP table is mutable which have composite parimary key, and have 5
local indexes.
I always upsert data from phoenix only.
Phoenix Configuration is below,
phoenix.schema.dropMetaData false
phoenix.query.rowKeyOrderSaltedTable true
hbase.regionserver.wal.codec
org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec
hbase.region.server.rpc.scheduler.factory.class
org.apache.hadoop.hbase.ipc.PhoenixRpcSchedulerFactory
phoenix.index.failure.block.write true
How can i solve this?
Please advise me if you do not mind.
Thanks,
Takashi
Re: Exception ERROR 201 (22000): Illegal data. Expected length of at
least 8 bytes, but had 4
Posted by Takashi Sasaki <ts...@gmail.com>.
Hi Josh,
PHOENIX-3453 is a similar phenomenon, but it seems to be different exactly.
I executed query directly, but the error wasn't occur.
Perhaps it is a complex cause.
I'm using HBase with AWS S3 storage mode, and wrapping JDBC with
MyBATIS, and so on.
I'll report it again when the same problem occurs in the latest version.
Thanks,
Takashi
2017-07-06 22:27 GMT+09:00 Josh Mahonin <jm...@gmail.com>:
> Hi Takashi,
>
> Thanks for the update. Do you think it could be the same issue as
> https://issues.apache.org/jira/browse/PHOENIX-3453 ?
>
> If not, it would be great if you could file a new JIRA ticket with as much
> detail as possible, and ideally a simple way to reproduce it.
>
> Thanks!
>
> Josh
>
> On Thu, Jul 6, 2017 at 6:36 AM, Takashi Sasaki <ts...@gmail.com> wrote:
>>
>> Hi Josh,
>>
>>
>> Well, it is difficult soon. I'll execute query directly if I have time.
>>
>> Information on the table is difficult to post due to confidentiality
>> agreement, but negotiate with my boss and provide it if possible.
>>
>> By the way, changing all local indexes to all global indexes no longer
>> causes the exception.
>>
>> It seems there is a problem with the local index.
>>
>>
>> Thanks,
>>
>> Takashi
>>
>>
>> 2017-07-05 22:35 GMT+09:00 Josh Mahonin <jm...@gmail.com>:
>> > Hi,
>> >
>> > From the logs you attached, it appears that you're getting the exception
>> > on
>> > the following query:
>> >
>> > SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
>> > oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
>> > cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
>> > DESC NULLS LAST FETCH FIRST 1 ROW ONLY
>> >
>> > Are you able to reproduce this issue by executing that query directly?
>> > Given
>> > a snippet of your stack trace, I'm not sure if Spark is the culprit
>> > here, so
>> > it'd be nice to try identify the root cause (or maybe correlate it to an
>> > existing JIRA ticket)
>> >
>> > ...
>> > Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> > ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
>> > at least 8 bytes, but had 4
>> >
>> > TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> > at
>> >
>> > org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> > at
>> >
>> > org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> > at
>> >
>> > org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
>> > at
>> >
>> > org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
>> > at
>> >
>> > org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
>> > at
>> >
>> > org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:755)
>> > at
>> >
>> > org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:699)
>> > at
>> >
>> > org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(MergeSortResultIterator.java:72)
>> > at
>> >
>> > org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(MergeSortResultIterator.java:93)
>> > at
>> >
>> > org.apache.phoenix.iterate.MergeSortResultIterator.next(MergeSortResultIterator.java:58)
>> > at
>> >
>> > org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(MergeSortTopNResultIterator.java:95)
>> > at
>> > org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
>> > ...
>> >
>> > Also, are you able to post your CREATE TABLE DDL for the 'trp' table
>> > you're
>> > querying?
>> >
>> > Thanks,
>> >
>> > Josh
>> >
>> > On Wed, Jul 5, 2017 at 1:24 AM, Takashi Sasaki <ts...@gmail.com>
>> > wrote:
>> >>
>> >> Hi,
>> >>
>> >> I'm using Phoenix4.9.0/HBase1.3.0 with Spark2.1.1 on AWS EMR 5.6.0.
>> >>
>> >> When one side uses Spark Streaming to write a lot of data and the
>> >> other side uses Spark to read data,
>> >> I encounter several similar exceptions.
>> >>
>> >> 17/07/05 04:33:47 ERROR Executor: Exception in task 83.0 in stage
>> >> 166.0 (TID 95211)
>> >> org.apache.ibatis.exceptions.PersistenceException:
>> >> ### Error querying database. Cause: java.sql.SQLException: ERROR 201
>> >> (22000): Illegal data. ERROR 201 (22000): ERROR 201 (22000): Illegal
>> >> data. Expected length of at least 8 bytes, but had 4
>> >>
>> >>
>> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> >> ### The error may exist in agp/mapper/TripMapper.java (best guess)
>> >> ### The error may involve agp.mapper.TripMapper.selectLast
>> >> ### The error occurred while handling results
>> >> ### SQL: SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
>> >> oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
>> >> cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
>> >> DESC NULLS LAST FETCH FIRST 1 ROW ONLY
>> >> ### Cause: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> >> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
>> >> at least 8 bytes, but had 4
>> >>
>> >>
>> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> >> at
>> >>
>> >> org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
>> >> at
>> >>
>> >> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:150)
>> >> at
>> >>
>> >> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
>> >> at
>> >>
>> >> org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
>> >> at
>> >> org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
>> >> at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
>> >> at com.sun.proxy.$Proxy38.selectLast(Unknown Source)
>> >> at agp.dao.TripDAO.selectLast(TripDAO.java:55)
>> >> at
>> >>
>> >> agp.trip.func.trip.SelectTripCondition.fixAccOnLocation(SelectTripCondition.java:128)
>> >> at
>> >>
>> >> agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:65)
>> >> at
>> >>
>> >> agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:25)
>> >> at
>> >>
>> >> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
>> >> at
>> >>
>> >> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
>> >> at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:434)
>> >> at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:440)
>> >> at scala.collection.Iterator$$anon$13.hasNext(Iterator.scala:461)
>> >> at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408)
>> >> at
>> >>
>> >> org.apache.spark.shuffle.sort.UnsafeShuffleWriter.write(UnsafeShuffleWriter.java:166)
>> >> at
>> >>
>> >> org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:96)
>> >> at
>> >>
>> >> org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:53)
>> >> at org.apache.spark.scheduler.Task.run(Task.scala:99)
>> >> at
>> >> org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:322)
>> >> at
>> >>
>> >> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> >> at
>> >>
>> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> >> at java.lang.Thread.run(Thread.java:748)
>> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> >> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
>> >> at least 8 bytes, but had 4
>> >>
>> >>
>> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:755)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:699)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(MergeSortResultIterator.java:72)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(MergeSortResultIterator.java:93)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.MergeSortResultIterator.next(MergeSortResultIterator.java:58)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(MergeSortTopNResultIterator.java:95)
>> >> at
>> >>
>> >> org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
>> >> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
>> >> at
>> >>
>> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> >> at java.lang.reflect.Method.invoke(Method.java:498)
>> >> at
>> >>
>> >> org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:68)
>> >> at com.sun.proxy.$Proxy37.next(Unknown Source)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:345)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:322)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:295)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:192)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
>> >> at
>> >> org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
>> >> at
>> >>
>> >> org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83)
>> >> at
>> >>
>> >> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
>> >> ... 23 more
>> >> Caused by: org.apache.hadoop.hbase.DoNotRetryIOException:
>> >> org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 201 (22000):
>> >> ERROR 201 (22000): Illegal data. Expected length of at least 8 bytes,
>> >> but had 4
>> >>
>> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.createIOException(ServerUtil.java:81)
>> >> at
>> >> org.apache.phoenix.util.ServerUtil.throwIOException(ServerUtil.java:55)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:328)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.ScanRegionObserver.doPostScannerOpen(ScanRegionObserver.java:241)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.overrideDelegate(BaseScannerRegionObserver.java:215)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.nextRaw(BaseScannerRegionObserver.java:260)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2633)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2837)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34950)
>> >> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
>> >> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
>> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> >> Expected length of at least 8 bytes, but had 4
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
>> >> at
>> >>
>> >> org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:61)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.OrderedResultIterator.getResultIterator(OrderedResultIterator.java:254)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.OrderedResultIterator.next(OrderedResultIterator.java:198)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:323)
>> >> ... 10 more
>> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> >> Expected length of at least 8 bytes, but had 4
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> >> at
>> >>
>> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> >> at
>> >> org.apache.phoenix.schema.KeyValueSchema.next(KeyValueSchema.java:213)
>> >> at
>> >>
>> >> org.apache.phoenix.expression.ProjectedColumnExpression.evaluate(ProjectedColumnExpression.java:115)
>> >> at
>> >>
>> >> org.apache.phoenix.schema.KeyValueSchema.toBytes(KeyValueSchema.java:112)
>> >> at
>> >>
>> >> org.apache.phoenix.execute.TupleProjector.projectResults(TupleProjector.java:245)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$1.nextRaw(BaseScannerRegionObserver.java:441)
>> >> at
>> >>
>> >> org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:50)
>> >> ... 13 more
>> >> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
>> >> Method)
>> >> at
>> >>
>> >> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
>> >> at
>> >>
>> >> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
>> >> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(RemoteExceptionHandler.java:97)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:272)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:64)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithoutRetries(RpcRetryingCaller.java:200)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:360)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:334)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:126)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture.run(ResultBoundedCompletionService.java:65)
>> >> ... 3 more
>> >>
>> >> HBase Region Server Logs below,
>> >> 1.
>> >> 2017-07-05 04:33:41,181 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >> 2017-07-05 04:33:50,929 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 2.
>> >> 2017-07-05 04:32:52,087 INFO [sync.2] wal.FSHLog: Slow sync cost: 104
>> >> ms, current pipeline:
>> >>
>> >>
>> >> [DatanodeInfoWithStorage[172.31.10.147:50010,DS-289c3237-9ec2-4abc-9fe8-e114fde75483,DISK],
>> >>
>> >>
>> >> DatanodeInfoWithStorage[172.31.8.18:50010,DS-5887519a-6424-4bf9-9c09-35d9b13b5b1d,DISK],
>> >>
>> >>
>> >> DatanodeInfoWithStorage[172.31.10.188:50010,DS-0c7f1e59-1719-4f5d-a400-79276b4469d1,DISK]]
>> >> 2017-07-05 04:34:31,791 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 3.
>> >> 2017-07-05 04:32:54,447 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.87 MB, cacheSize=1.87 MB, accesses=802,
>> >> hits=261, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=32.54%,
>> >> cachingAccesses=372, cachingHits=196, cachingHitsRatio=52.69%,
>> >> evictions=0, evicted=65, evictedPerRun=Infinity
>> >> 2017-07-05 04:34:18,621 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 4.
>> >> 2017-07-05 04:33:41,653 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >> 2017-07-05 04:33:50,601 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 5.
>> >> 2017-07-05 04:32:04,566 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.82 MB, cacheSize=1.85 MB, accesses=300,
>> >> hits=114, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=38.00%,
>> >> cachingAccesses=203, cachingHits=114, cachingHitsRatio=56.16%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:33:41,167 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 6.
>> >> 2017-07-05 04:31:52,910 INFO
>> >>
>> >>
>> >> [ip-172-31-11-39.ap-northeast-1.compute.internal,16020,1499227300627-index-writer--pool30-t13]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRB,\x0C\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.f0fade12881d6c99e9674639c90acad1.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
>> >> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
>> >> GB, blockCount=2, accesses=49007, hits=49007, hitRatio=100.00%, ,
>> >> cachingAccesses=49007, cachingHits=49007, cachingHitsRatio=100.00%,
>> >> evictions=179, evicted=0, evictedPerRun=0.0
>> >> 2017-07-05 04:32:04,581 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=79.99 GB, usedSize=5.59 MB, cacheSize=3.66 MB, accesses=599,
>> >> hits=218, IOhitsPerSecond=0, IOTimePerHit=0.09, hitRatio=36.39%,
>> >> cachingAccesses=402, cachingHits=218, cachingHitsRatio=54.23%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:33:46,020 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 7.
>> >> 2017-07-05 04:31:53,027 INFO
>> >>
>> >>
>> >> [ip-172-31-12-156.ap-northeast-1.compute.internal,16020,1499227465864-index-writer--pool26-t15]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRB,\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.31b5cfcc09891813241932c46e2e6d5b.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:34:10,233 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >> 2017-07-05 04:34:29,590 INFO [LruBlockCacheStatsExecutor]
>> >> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
>> >> GB, blockCount=2, accesses=27170, hits=27170, hitRatio=100.00%, ,
>> >> cachingAccesses=27170, cachingHits=27170, cachingHitsRatio=100.00%,
>> >> evictions=179, evicted=0, evictedPerRun=0.0
>> >> 2017-07-05 04:34:29,643 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.90 MB, cacheSize=1.90 MB, accesses=295,
>> >> hits=98, IOhitsPerSecond=0, IOTimePerHit=NaN, hitRatio=33.22%,
>> >> cachingAccesses=200, cachingHits=98, cachingHitsRatio=49.00%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:35:13,274 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 8.
>> >> 2017-07-05 04:27:41,202 ERROR
>> >> [RpcServer.FifoWFPBQ.default.handler=29,queue=2,port=16020]
>> >> coprocessor.MetaDataEndpointImpl: getTable failed
>> >> org.apache.hadoop.hbase.NotServingRegionException:
>> >> SYSTEM.CATALOG,,1499216017494.3bbe2fb5b186285a9555b45c87684cc7. is
>> >> closing
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.HRegion.startRegionOperation(HRegion.java:8291)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2645)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2640)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2634)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.buildTable(MetaDataEndpointImpl.java:533)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2939)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2884)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.getTable(MetaDataEndpointImpl.java:492)
>> >> at
>> >>
>> >> org.apache.phoenix.coprocessor.generated.MetaDataProtos$MetaDataService.callMethod(MetaDataProtos.java:16267)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.HRegion.execService(HRegion.java:8095)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnRegion(RSRpcServices.java:2072)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.execService(RSRpcServices.java:2054)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34954)
>> >> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
>> >> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
>> >> at
>> >>
>> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
>> >> 2017-07-05 04:31:53,017 INFO
>> >>
>> >>
>> >> [ip-172-31-14-56.ap-northeast-1.compute.internal,16020,1499227310987-index-writer--pool43-t18]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRB,\x07\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.c93f2a12e912e9501f0801e9cb73f75c.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:32:04,571 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=3.01 MB, cacheSize=1.97 MB, accesses=1077,
>> >> hits=881, IOhitsPerSecond=0, IOTimePerHit=0.16, hitRatio=81.80%,
>> >> cachingAccesses=980, cachingHits=881, cachingHitsRatio=89.90%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:36:34,114 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 9.
>> >> 2017-07-05 04:31:52,915 INFO
>> >>
>> >>
>> >> [ip-172-31-3-154.ap-northeast-1.compute.internal,16020,1499227309930-index-writer--pool3-t13]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRB,\x0D\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.9eca4d9d19a712533aa240853173c816.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:32:04,506 INFO [LruBlockCacheStatsExecutor]
>> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> >> GB, blockCount=4, accesses=26651, hits=26651, hitRatio=100.00%, ,
>> >> cachingAccesses=26651, cachingHits=26651, cachingHitsRatio=100.00%,
>> >> evictions=179, evicted=0, evictedPerRun=0.0
>> >> 2017-07-05 04:32:04,556 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.85 MB, cacheSize=1.85 MB, accesses=334,
>> >> hits=134, IOhitsPerSecond=0, IOTimePerHit=0.15, hitRatio=40.12%,
>> >> cachingAccesses=239, cachingHits=134, cachingHitsRatio=56.07%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:33:33,010 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >> 2017-07-05 04:33:40,823 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 10.
>> >> 2017-07-05 04:31:53,653 INFO
>> >>
>> >>
>> >> [ip-172-31-7-66.ap-northeast-1.compute.internal,16020,1499227313375-index-writer--pool38-t18]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRP,\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.6706144c5be72f993a69ad9ad63005e5.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
>> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> >> GB, blockCount=1, accesses=24493, hits=24493, hitRatio=100.00%, ,
>> >> cachingAccesses=24493, cachingHits=24493, cachingHitsRatio=100.00%,
>> >> evictions=179, evicted=0, evictedPerRun=0.0
>> >> 2017-07-05 04:32:04,577 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.48 MB, cacheSize=1.62 MB, accesses=260,
>> >> hits=81, IOhitsPerSecond=0, IOTimePerHit=0.10, hitRatio=31.15%,
>> >> cachingAccesses=164, cachingHits=81, cachingHitsRatio=49.39%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:36:04,834 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> 11.
>> >> 2017-07-05 04:31:53,327 INFO
>> >>
>> >>
>> >> [ip-172-31-8-18.ap-northeast-1.compute.internal,16020,1499227319500-index-writer--pool26-t18]
>> >> regionserver.HRegion: writing data to region
>> >>
>> >>
>> >> TRP,\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.53d87d4772b4e637b4dfd426bb11d624.
>> >> with WAL disabled. Data may be lost in the event of a crash.
>> >> 2017-07-05 04:32:04,505 INFO [LruBlockCacheStatsExecutor]
>> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> >> GB, blockCount=1, accesses=23309, hits=23309, hitRatio=100.00%, ,
>> >> cachingAccesses=23309, cachingHits=23309, cachingHitsRatio=100.00%,
>> >> evictions=179, evicted=0, evictedPerRun=0.0
>> >> 2017-07-05 04:32:04,574 INFO [BucketCacheStatsExecutor]
>> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> >> freeSize=80.00 GB, usedSize=2.83 MB, cacheSize=1.85 MB, accesses=330,
>> >> hits=138, IOhitsPerSecond=0, IOTimePerHit=0.12, hitRatio=41.82%,
>> >> cachingAccesses=232, cachingHits=138, cachingHitsRatio=59.48%,
>> >> evictions=0, evicted=0, evictedPerRun=NaN
>> >> 2017-07-05 04:33:58,658 WARN [Finalizer] memory.GlobalMemoryManager:
>> >> Orphaned chunk of 104 bytes found during finalize
>> >>
>> >> The TRP table is mutable which have composite parimary key, and have 5
>> >> local indexes.
>> >> I always upsert data from phoenix only.
>> >>
>> >> Phoenix Configuration is below,
>> >> phoenix.schema.dropMetaData false
>> >> phoenix.query.rowKeyOrderSaltedTable true
>> >> hbase.regionserver.wal.codec
>> >> org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec
>> >> hbase.region.server.rpc.scheduler.factory.class
>> >> org.apache.hadoop.hbase.ipc.PhoenixRpcSchedulerFactory
>> >> phoenix.index.failure.block.write true
>> >>
>> >> How can i solve this?
>> >> Please advise me if you do not mind.
>> >>
>> >> Thanks,
>> >> Takashi
>> >
>> >
>
>
Re: Exception ERROR 201 (22000): Illegal data. Expected length of at
least 8 bytes, but had 4
Posted by Josh Mahonin <jm...@gmail.com>.
Hi Takashi,
Thanks for the update. Do you think it could be the same issue as
https://issues.apache.org/jira/browse/PHOENIX-3453 ?
If not, it would be great if you could file a new JIRA ticket with as much
detail as possible, and ideally a simple way to reproduce it.
Thanks!
Josh
On Thu, Jul 6, 2017 at 6:36 AM, Takashi Sasaki <ts...@gmail.com> wrote:
> Hi Josh,
>
>
> Well, it is difficult soon. I'll execute query directly if I have time.
>
> Information on the table is difficult to post due to confidentiality
> agreement, but negotiate with my boss and provide it if possible.
>
> By the way, changing all local indexes to all global indexes no longer
> causes the exception.
>
> It seems there is a problem with the local index.
>
>
> Thanks,
>
> Takashi
>
>
> 2017-07-05 22:35 GMT+09:00 Josh Mahonin <jm...@gmail.com>:
> > Hi,
> >
> > From the logs you attached, it appears that you're getting the exception
> on
> > the following query:
> >
> > SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
> > oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
> > cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
> > DESC NULLS LAST FETCH FIRST 1 ROW ONLY
> >
> > Are you able to reproduce this issue by executing that query directly?
> Given
> > a snippet of your stack trace, I'm not sure if Spark is the culprit
> here, so
> > it'd be nice to try identify the root cause (or maybe correlate it to an
> > existing JIRA ticket)
> >
> > ...
> > Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> > ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> > at least 8 bytes, but had 4
> > TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> > at
> > org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> > at
> > org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> > at
> > org.apache.phoenix.util.ServerUtil.parseRemoteException(
> ServerUtil.java:134)
> > at
> > org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
> ServerUtil.java:123)
> > at
> > org.apache.phoenix.util.ServerUtil.parseServerException(
> ServerUtil.java:109)
> > at
> > org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:755)
> > at
> > org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:699)
> > at
> > org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(
> MergeSortResultIterator.java:72)
> > at
> > org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(
> MergeSortResultIterator.java:93)
> > at
> > org.apache.phoenix.iterate.MergeSortResultIterator.next(
> MergeSortResultIterator.java:58)
> > at
> > org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(
> MergeSortTopNResultIterator.java:95)
> > at org.apache.phoenix.jdbc.PhoenixResultSet.next(
> PhoenixResultSet.java:778)
> > ...
> >
> > Also, are you able to post your CREATE TABLE DDL for the 'trp' table
> you're
> > querying?
> >
> > Thanks,
> >
> > Josh
> >
> > On Wed, Jul 5, 2017 at 1:24 AM, Takashi Sasaki <ts...@gmail.com>
> wrote:
> >>
> >> Hi,
> >>
> >> I'm using Phoenix4.9.0/HBase1.3.0 with Spark2.1.1 on AWS EMR 5.6.0.
> >>
> >> When one side uses Spark Streaming to write a lot of data and the
> >> other side uses Spark to read data,
> >> I encounter several similar exceptions.
> >>
> >> 17/07/05 04:33:47 ERROR Executor: Exception in task 83.0 in stage
> >> 166.0 (TID 95211)
> >> org.apache.ibatis.exceptions.PersistenceException:
> >> ### Error querying database. Cause: java.sql.SQLException: ERROR 201
> >> (22000): Illegal data. ERROR 201 (22000): ERROR 201 (22000): Illegal
> >> data. Expected length of at least 8 bytes, but had 4
> >>
> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> >> ### The error may exist in agp/mapper/TripMapper.java (best guess)
> >> ### The error may involve agp.mapper.TripMapper.selectLast
> >> ### The error occurred while handling results
> >> ### SQL: SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
> >> oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
> >> cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
> >> DESC NULLS LAST FETCH FIRST 1 ROW ONLY
> >> ### Cause: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> >> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> >> at least 8 bytes, but had 4
> >>
> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> >> at
> >> org.apache.ibatis.exceptions.ExceptionFactory.wrapException(
> ExceptionFactory.java:30)
> >> at
> >> org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:150)
> >> at
> >> org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:141)
> >> at
> >> org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectOne(DefaultSqlSession.java:77)
> >> at org.apache.ibatis.binding.MapperMethod.execute(
> MapperMethod.java:82)
> >> at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
> >> at com.sun.proxy.$Proxy38.selectLast(Unknown Source)
> >> at agp.dao.TripDAO.selectLast(TripDAO.java:55)
> >> at
> >> agp.trip.func.trip.SelectTripCondition.fixAccOnLocation(
> SelectTripCondition.java:128)
> >> at
> >> agp.trip.func.trip.SelectTripCondition.call(
> SelectTripCondition.java:65)
> >> at
> >> agp.trip.func.trip.SelectTripCondition.call(
> SelectTripCondition.java:25)
> >> at
> >> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.
> apply(JavaRDDLike.scala:125)
> >> at
> >> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.
> apply(JavaRDDLike.scala:125)
> >> at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:434)
> >> at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:440)
> >> at scala.collection.Iterator$$anon$13.hasNext(Iterator.scala:461)
> >> at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408)
> >> at
> >> org.apache.spark.shuffle.sort.UnsafeShuffleWriter.write(
> UnsafeShuffleWriter.java:166)
> >> at
> >> org.apache.spark.scheduler.ShuffleMapTask.runTask(
> ShuffleMapTask.scala:96)
> >> at
> >> org.apache.spark.scheduler.ShuffleMapTask.runTask(
> ShuffleMapTask.scala:53)
> >> at org.apache.spark.scheduler.Task.run(Task.scala:99)
> >> at org.apache.spark.executor.Executor$TaskRunner.run(
> Executor.scala:322)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor.runWorker(
> ThreadPoolExecutor.java:1142)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java:617)
> >> at java.lang.Thread.run(Thread.java:748)
> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> >> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> >> at least 8 bytes, but had 4
> >>
> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> >> at
> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> >> at
> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseRemoteException(
> ServerUtil.java:134)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
> ServerUtil.java:123)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseServerException(
> ServerUtil.java:109)
> >> at
> >> org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:755)
> >> at
> >> org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:699)
> >> at
> >> org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(
> MergeSortResultIterator.java:72)
> >> at
> >> org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(
> MergeSortResultIterator.java:93)
> >> at
> >> org.apache.phoenix.iterate.MergeSortResultIterator.next(
> MergeSortResultIterator.java:58)
> >> at
> >> org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(
> MergeSortTopNResultIterator.java:95)
> >> at
> >> org.apache.phoenix.jdbc.PhoenixResultSet.next(
> PhoenixResultSet.java:778)
> >> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> >> at
> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(
> DelegatingMethodAccessorImpl.java:43)
> >> at java.lang.reflect.Method.invoke(Method.java:498)
> >> at
> >> org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(
> ResultSetLogger.java:68)
> >> at com.sun.proxy.$Proxy37.next(Unknown Source)
> >> at
> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:345)
> >> at
> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleRowValues(DefaultResultSetHandler.java:322)
> >> at
> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleResultSet(DefaultResultSetHandler.java:295)
> >> at
> >> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleResultSets(DefaultResultSetHandler.java:192)
> >> at
> >> org.apache.ibatis.executor.statement.PreparedStatementHandler.query(
> PreparedStatementHandler.java:64)
> >> at
> >> org.apache.ibatis.executor.statement.RoutingStatementHandler.query(
> RoutingStatementHandler.java:79)
> >> at
> >> org.apache.ibatis.executor.SimpleExecutor.doQuery(
> SimpleExecutor.java:63)
> >> at
> >> org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(
> BaseExecutor.java:324)
> >> at org.apache.ibatis.executor.BaseExecutor.query(
> BaseExecutor.java:156)
> >> at
> >> org.apache.ibatis.executor.CachingExecutor.query(
> CachingExecutor.java:109)
> >> at
> >> org.apache.ibatis.executor.CachingExecutor.query(
> CachingExecutor.java:83)
> >> at
> >> org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:148)
> >> ... 23 more
> >> Caused by: org.apache.hadoop.hbase.DoNotRetryIOException:
> >> org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 201 (22000):
> >> ERROR 201 (22000): Illegal data. Expected length of at least 8 bytes,
> >> but had 4
> >> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> >> at
> >> org.apache.phoenix.util.ServerUtil.createIOException(
> ServerUtil.java:81)
> >> at
> >> org.apache.phoenix.util.ServerUtil.throwIOException(ServerUtil.java:55)
> >> at
> >> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(
> ScanRegionObserver.java:328)
> >> at
> >> org.apache.phoenix.coprocessor.ScanRegionObserver.doPostScannerOpen(
> ScanRegionObserver.java:241)
> >> at
> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$
> RegionScannerHolder.overrideDelegate(BaseScannerRegionObserver.java:215)
> >> at
> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$
> RegionScannerHolder.nextRaw(BaseScannerRegionObserver.java:260)
> >> at
> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.
> scan(RSRpcServices.java:2633)
> >> at
> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.
> scan(RSRpcServices.java:2837)
> >> at
> >> org.apache.hadoop.hbase.protobuf.generated.
> ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34950)
> >> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
> >> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
> >> at
> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:188)
> >> at
> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:168)
> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> >> Expected length of at least 8 bytes, but had 4
> >> at
> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> >> at
> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseRemoteException(
> ServerUtil.java:134)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
> ServerUtil.java:123)
> >> at
> >> org.apache.phoenix.util.ServerUtil.parseServerException(
> ServerUtil.java:109)
> >> at
> >> org.apache.phoenix.iterate.RegionScannerResultIterator.next(
> RegionScannerResultIterator.java:61)
> >> at
> >> org.apache.phoenix.iterate.OrderedResultIterator.getResultIterator(
> OrderedResultIterator.java:254)
> >> at
> >> org.apache.phoenix.iterate.OrderedResultIterator.next(
> OrderedResultIterator.java:198)
> >> at
> >> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(
> ScanRegionObserver.java:323)
> >> ... 10 more
> >> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> >> Expected length of at least 8 bytes, but had 4
> >> at
> >> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> >> at
> >> org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> >> at org.apache.phoenix.schema.KeyValueSchema.next(
> KeyValueSchema.java:213)
> >> at
> >> org.apache.phoenix.expression.ProjectedColumnExpression.evaluate(
> ProjectedColumnExpression.java:115)
> >> at
> >> org.apache.phoenix.schema.KeyValueSchema.toBytes(
> KeyValueSchema.java:112)
> >> at
> >> org.apache.phoenix.execute.TupleProjector.projectResults(
> TupleProjector.java:245)
> >> at
> >> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$1.nextRaw(
> BaseScannerRegionObserver.java:441)
> >> at
> >> org.apache.phoenix.iterate.RegionScannerResultIterator.next(
> RegionScannerResultIterator.java:50)
> >> ... 13 more
> >> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
> Method)
> >> at
> >> sun.reflect.NativeConstructorAccessorImpl.newInstance(
> NativeConstructorAccessorImpl.java:62)
> >> at
> >> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(
> DelegatingConstructorAccessorImpl.java:45)
> >> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> >> at
> >> org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(
> RemoteExceptionHandler.java:97)
> >> at
> >> org.apache.hadoop.hbase.client.ScannerCallable.call(
> ScannerCallable.java:272)
> >> at
> >> org.apache.hadoop.hbase.client.ScannerCallable.call(
> ScannerCallable.java:64)
> >> at
> >> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithoutRetries(
> RpcRetryingCaller.java:200)
> >> at
> >> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$
> RetryingRPC.call(ScannerCallableWithReplicas.java:360)
> >> at
> >> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$
> RetryingRPC.call(ScannerCallableWithReplicas.java:334)
> >> at
> >> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(
> RpcRetryingCaller.java:126)
> >> at
> >> org.apache.hadoop.hbase.client.ResultBoundedCompletionService
> $QueueingFuture.run(ResultBoundedCompletionService.java:65)
> >> ... 3 more
> >>
> >> HBase Region Server Logs below,
> >> 1.
> >> 2017-07-05 04:33:41,181 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >> 2017-07-05 04:33:50,929 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 2.
> >> 2017-07-05 04:32:52,087 INFO [sync.2] wal.FSHLog: Slow sync cost: 104
> >> ms, current pipeline:
> >>
> >> [DatanodeInfoWithStorage[172.31.10.147:50010,DS-289c3237-
> 9ec2-4abc-9fe8-e114fde75483,DISK],
> >>
> >> DatanodeInfoWithStorage[172.31.8.18:50010,DS-5887519a-
> 6424-4bf9-9c09-35d9b13b5b1d,DISK],
> >>
> >> DatanodeInfoWithStorage[172.31.10.188:50010,DS-0c7f1e59-
> 1719-4f5d-a400-79276b4469d1,DISK]]
> >> 2017-07-05 04:34:31,791 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 3.
> >> 2017-07-05 04:32:54,447 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.87 MB, cacheSize=1.87 MB, accesses=802,
> >> hits=261, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=32.54%,
> >> cachingAccesses=372, cachingHits=196, cachingHitsRatio=52.69%,
> >> evictions=0, evicted=65, evictedPerRun=Infinity
> >> 2017-07-05 04:34:18,621 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 4.
> >> 2017-07-05 04:33:41,653 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >> 2017-07-05 04:33:50,601 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 5.
> >> 2017-07-05 04:32:04,566 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.82 MB, cacheSize=1.85 MB, accesses=300,
> >> hits=114, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=38.00%,
> >> cachingAccesses=203, cachingHits=114, cachingHitsRatio=56.16%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:33:41,167 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 6.
> >> 2017-07-05 04:31:52,910 INFO
> >>
> >> [ip-172-31-11-39.ap-northeast-1.compute.internal,16020,
> 1499227300627-index-writer--pool30-t13]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRB,\x0C\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.f0fade12881d6c99e9674639c90acad1.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
> >> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
> >> GB, blockCount=2, accesses=49007, hits=49007, hitRatio=100.00%, ,
> >> cachingAccesses=49007, cachingHits=49007, cachingHitsRatio=100.00%,
> >> evictions=179, evicted=0, evictedPerRun=0.0
> >> 2017-07-05 04:32:04,581 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=79.99 GB, usedSize=5.59 MB, cacheSize=3.66 MB, accesses=599,
> >> hits=218, IOhitsPerSecond=0, IOTimePerHit=0.09, hitRatio=36.39%,
> >> cachingAccesses=402, cachingHits=218, cachingHitsRatio=54.23%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:33:46,020 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 7.
> >> 2017-07-05 04:31:53,027 INFO
> >>
> >> [ip-172-31-12-156.ap-northeast-1.compute.internal,
> 16020,1499227465864-index-writer--pool26-t15]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRB,\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.31b5cfcc09891813241932c46e2e6d5b.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:34:10,233 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >> 2017-07-05 04:34:29,590 INFO [LruBlockCacheStatsExecutor]
> >> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
> >> GB, blockCount=2, accesses=27170, hits=27170, hitRatio=100.00%, ,
> >> cachingAccesses=27170, cachingHits=27170, cachingHitsRatio=100.00%,
> >> evictions=179, evicted=0, evictedPerRun=0.0
> >> 2017-07-05 04:34:29,643 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.90 MB, cacheSize=1.90 MB, accesses=295,
> >> hits=98, IOhitsPerSecond=0, IOTimePerHit=NaN, hitRatio=33.22%,
> >> cachingAccesses=200, cachingHits=98, cachingHitsRatio=49.00%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:35:13,274 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 8.
> >> 2017-07-05 04:27:41,202 ERROR
> >> [RpcServer.FifoWFPBQ.default.handler=29,queue=2,port=16020]
> >> coprocessor.MetaDataEndpointImpl: getTable failed
> >> org.apache.hadoop.hbase.NotServingRegionException:
> >> SYSTEM.CATALOG,,1499216017494.3bbe2fb5b186285a9555b45c87684cc7. is
> >> closing
> >> at
> >> org.apache.hadoop.hbase.regionserver.HRegion.
> startRegionOperation(HRegion.java:8291)
> >> at
> >> org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2645)
> >> at
> >> org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2640)
> >> at
> >> org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2634)
> >> at
> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.buildTable(
> MetaDataEndpointImpl.java:533)
> >> at
> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(
> MetaDataEndpointImpl.java:2939)
> >> at
> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(
> MetaDataEndpointImpl.java:2884)
> >> at
> >> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.getTable(
> MetaDataEndpointImpl.java:492)
> >> at
> >> org.apache.phoenix.coprocessor.generated.MetaDataProtos$
> MetaDataService.callMethod(MetaDataProtos.java:16267)
> >> at
> >> org.apache.hadoop.hbase.regionserver.HRegion.
> execService(HRegion.java:8095)
> >> at
> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnRegion(
> RSRpcServices.java:2072)
> >> at
> >> org.apache.hadoop.hbase.regionserver.RSRpcServices.
> execService(RSRpcServices.java:2054)
> >> at
> >> org.apache.hadoop.hbase.protobuf.generated.
> ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34954)
> >> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
> >> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
> >> at
> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:188)
> >> at
> >> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:168)
> >> 2017-07-05 04:31:53,017 INFO
> >>
> >> [ip-172-31-14-56.ap-northeast-1.compute.internal,16020,
> 1499227310987-index-writer--pool43-t18]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRB,\x07\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.c93f2a12e912e9501f0801e9cb73f75c.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:32:04,571 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=3.01 MB, cacheSize=1.97 MB, accesses=1077,
> >> hits=881, IOhitsPerSecond=0, IOTimePerHit=0.16, hitRatio=81.80%,
> >> cachingAccesses=980, cachingHits=881, cachingHitsRatio=89.90%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:36:34,114 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 9.
> >> 2017-07-05 04:31:52,915 INFO
> >>
> >> [ip-172-31-3-154.ap-northeast-1.compute.internal,16020,
> 1499227309930-index-writer--pool3-t13]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRB,\x0D\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.9eca4d9d19a712533aa240853173c816.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:32:04,506 INFO [LruBlockCacheStatsExecutor]
> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> >> GB, blockCount=4, accesses=26651, hits=26651, hitRatio=100.00%, ,
> >> cachingAccesses=26651, cachingHits=26651, cachingHitsRatio=100.00%,
> >> evictions=179, evicted=0, evictedPerRun=0.0
> >> 2017-07-05 04:32:04,556 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.85 MB, cacheSize=1.85 MB, accesses=334,
> >> hits=134, IOhitsPerSecond=0, IOTimePerHit=0.15, hitRatio=40.12%,
> >> cachingAccesses=239, cachingHits=134, cachingHitsRatio=56.07%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:33:33,010 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >> 2017-07-05 04:33:40,823 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 10.
> >> 2017-07-05 04:31:53,653 INFO
> >>
> >> [ip-172-31-7-66.ap-northeast-1.compute.internal,16020,
> 1499227313375-index-writer--pool38-t18]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRP,\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.6706144c5be72f993a69ad9ad63005e5.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> >> GB, blockCount=1, accesses=24493, hits=24493, hitRatio=100.00%, ,
> >> cachingAccesses=24493, cachingHits=24493, cachingHitsRatio=100.00%,
> >> evictions=179, evicted=0, evictedPerRun=0.0
> >> 2017-07-05 04:32:04,577 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.48 MB, cacheSize=1.62 MB, accesses=260,
> >> hits=81, IOhitsPerSecond=0, IOTimePerHit=0.10, hitRatio=31.15%,
> >> cachingAccesses=164, cachingHits=81, cachingHitsRatio=49.39%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:36:04,834 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> 11.
> >> 2017-07-05 04:31:53,327 INFO
> >>
> >> [ip-172-31-8-18.ap-northeast-1.compute.internal,16020,
> 1499227319500-index-writer--pool26-t18]
> >> regionserver.HRegion: writing data to region
> >>
> >> TRP,\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.53d87d4772b4e637b4dfd426bb11d624.
> >> with WAL disabled. Data may be lost in the event of a crash.
> >> 2017-07-05 04:32:04,505 INFO [LruBlockCacheStatsExecutor]
> >> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> >> GB, blockCount=1, accesses=23309, hits=23309, hitRatio=100.00%, ,
> >> cachingAccesses=23309, cachingHits=23309, cachingHitsRatio=100.00%,
> >> evictions=179, evicted=0, evictedPerRun=0.0
> >> 2017-07-05 04:32:04,574 INFO [BucketCacheStatsExecutor]
> >> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> >> freeSize=80.00 GB, usedSize=2.83 MB, cacheSize=1.85 MB, accesses=330,
> >> hits=138, IOhitsPerSecond=0, IOTimePerHit=0.12, hitRatio=41.82%,
> >> cachingAccesses=232, cachingHits=138, cachingHitsRatio=59.48%,
> >> evictions=0, evicted=0, evictedPerRun=NaN
> >> 2017-07-05 04:33:58,658 WARN [Finalizer] memory.GlobalMemoryManager:
> >> Orphaned chunk of 104 bytes found during finalize
> >>
> >> The TRP table is mutable which have composite parimary key, and have 5
> >> local indexes.
> >> I always upsert data from phoenix only.
> >>
> >> Phoenix Configuration is below,
> >> phoenix.schema.dropMetaData false
> >> phoenix.query.rowKeyOrderSaltedTable true
> >> hbase.regionserver.wal.codec
> >> org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec
> >> hbase.region.server.rpc.scheduler.factory.class
> >> org.apache.hadoop.hbase.ipc.PhoenixRpcSchedulerFactory
> >> phoenix.index.failure.block.write true
> >>
> >> How can i solve this?
> >> Please advise me if you do not mind.
> >>
> >> Thanks,
> >> Takashi
> >
> >
>
Re: Exception ERROR 201 (22000): Illegal data. Expected length of at
least 8 bytes, but had 4
Posted by Takashi Sasaki <ts...@gmail.com>.
Hi Josh,
Well, it is difficult soon. I'll execute query directly if I have time.
Information on the table is difficult to post due to confidentiality
agreement, but negotiate with my boss and provide it if possible.
By the way, changing all local indexes to all global indexes no longer
causes the exception.
It seems there is a problem with the local index.
Thanks,
Takashi
2017-07-05 22:35 GMT+09:00 Josh Mahonin <jm...@gmail.com>:
> Hi,
>
> From the logs you attached, it appears that you're getting the exception on
> the following query:
>
> SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
> oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
> cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
> DESC NULLS LAST FETCH FIRST 1 ROW ONLY
>
> Are you able to reproduce this issue by executing that query directly? Given
> a snippet of your stack trace, I'm not sure if Spark is the culprit here, so
> it'd be nice to try identify the root cause (or maybe correlate it to an
> existing JIRA ticket)
>
> ...
> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> at least 8 bytes, but had 4
> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> at
> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
> at
> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
> at
> org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
> at
> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
> at
> org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
> at
> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:755)
> at
> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:699)
> at
> org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(MergeSortResultIterator.java:72)
> at
> org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(MergeSortResultIterator.java:93)
> at
> org.apache.phoenix.iterate.MergeSortResultIterator.next(MergeSortResultIterator.java:58)
> at
> org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(MergeSortTopNResultIterator.java:95)
> at org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
> ...
>
> Also, are you able to post your CREATE TABLE DDL for the 'trp' table you're
> querying?
>
> Thanks,
>
> Josh
>
> On Wed, Jul 5, 2017 at 1:24 AM, Takashi Sasaki <ts...@gmail.com> wrote:
>>
>> Hi,
>>
>> I'm using Phoenix4.9.0/HBase1.3.0 with Spark2.1.1 on AWS EMR 5.6.0.
>>
>> When one side uses Spark Streaming to write a lot of data and the
>> other side uses Spark to read data,
>> I encounter several similar exceptions.
>>
>> 17/07/05 04:33:47 ERROR Executor: Exception in task 83.0 in stage
>> 166.0 (TID 95211)
>> org.apache.ibatis.exceptions.PersistenceException:
>> ### Error querying database. Cause: java.sql.SQLException: ERROR 201
>> (22000): Illegal data. ERROR 201 (22000): ERROR 201 (22000): Illegal
>> data. Expected length of at least 8 bytes, but had 4
>>
>> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> ### The error may exist in agp/mapper/TripMapper.java (best guess)
>> ### The error may involve agp.mapper.TripMapper.selectLast
>> ### The error occurred while handling results
>> ### SQL: SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
>> oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
>> cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
>> DESC NULLS LAST FETCH FIRST 1 ROW ONLY
>> ### Cause: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
>> at least 8 bytes, but had 4
>>
>> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> at
>> org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
>> at
>> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:150)
>> at
>> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
>> at
>> org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
>> at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
>> at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
>> at com.sun.proxy.$Proxy38.selectLast(Unknown Source)
>> at agp.dao.TripDAO.selectLast(TripDAO.java:55)
>> at
>> agp.trip.func.trip.SelectTripCondition.fixAccOnLocation(SelectTripCondition.java:128)
>> at
>> agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:65)
>> at
>> agp.trip.func.trip.SelectTripCondition.call(SelectTripCondition.java:25)
>> at
>> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
>> at
>> org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.apply(JavaRDDLike.scala:125)
>> at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:434)
>> at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:440)
>> at scala.collection.Iterator$$anon$13.hasNext(Iterator.scala:461)
>> at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408)
>> at
>> org.apache.spark.shuffle.sort.UnsafeShuffleWriter.write(UnsafeShuffleWriter.java:166)
>> at
>> org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:96)
>> at
>> org.apache.spark.scheduler.ShuffleMapTask.runTask(ShuffleMapTask.scala:53)
>> at org.apache.spark.scheduler.Task.run(Task.scala:99)
>> at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:322)
>> at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:748)
>> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
>> at least 8 bytes, but had 4
>>
>> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> at
>> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> at
>> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> at
>> org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
>> at
>> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
>> at
>> org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
>> at
>> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:755)
>> at
>> org.apache.phoenix.iterate.BaseResultIterators.getIterators(BaseResultIterators.java:699)
>> at
>> org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(MergeSortResultIterator.java:72)
>> at
>> org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(MergeSortResultIterator.java:93)
>> at
>> org.apache.phoenix.iterate.MergeSortResultIterator.next(MergeSortResultIterator.java:58)
>> at
>> org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(MergeSortTopNResultIterator.java:95)
>> at
>> org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
>> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
>> at
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> at java.lang.reflect.Method.invoke(Method.java:498)
>> at
>> org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:68)
>> at com.sun.proxy.$Proxy37.next(Unknown Source)
>> at
>> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:345)
>> at
>> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:322)
>> at
>> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:295)
>> at
>> org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:192)
>> at
>> org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
>> at
>> org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
>> at
>> org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
>> at
>> org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
>> at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
>> at
>> org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
>> at
>> org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83)
>> at
>> org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
>> ... 23 more
>> Caused by: org.apache.hadoop.hbase.DoNotRetryIOException:
>> org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 201 (22000):
>> ERROR 201 (22000): Illegal data. Expected length of at least 8 bytes,
>> but had 4
>> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
>> at
>> org.apache.phoenix.util.ServerUtil.createIOException(ServerUtil.java:81)
>> at
>> org.apache.phoenix.util.ServerUtil.throwIOException(ServerUtil.java:55)
>> at
>> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:328)
>> at
>> org.apache.phoenix.coprocessor.ScanRegionObserver.doPostScannerOpen(ScanRegionObserver.java:241)
>> at
>> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.overrideDelegate(BaseScannerRegionObserver.java:215)
>> at
>> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$RegionScannerHolder.nextRaw(BaseScannerRegionObserver.java:260)
>> at
>> org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2633)
>> at
>> org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2837)
>> at
>> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34950)
>> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
>> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
>> at
>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
>> at
>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
>> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> Expected length of at least 8 bytes, but had 4
>> at
>> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> at
>> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> at
>> org.apache.phoenix.util.ServerUtil.parseRemoteException(ServerUtil.java:134)
>> at
>> org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(ServerUtil.java:123)
>> at
>> org.apache.phoenix.util.ServerUtil.parseServerException(ServerUtil.java:109)
>> at
>> org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:61)
>> at
>> org.apache.phoenix.iterate.OrderedResultIterator.getResultIterator(OrderedResultIterator.java:254)
>> at
>> org.apache.phoenix.iterate.OrderedResultIterator.next(OrderedResultIterator.java:198)
>> at
>> org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(ScanRegionObserver.java:323)
>> ... 10 more
>> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
>> Expected length of at least 8 bytes, but had 4
>> at
>> org.apache.phoenix.exception.SQLExceptionCode$Factory$1.newException(SQLExceptionCode.java:464)
>> at
>> org.apache.phoenix.exception.SQLExceptionInfo.buildException(SQLExceptionInfo.java:150)
>> at org.apache.phoenix.schema.KeyValueSchema.next(KeyValueSchema.java:213)
>> at
>> org.apache.phoenix.expression.ProjectedColumnExpression.evaluate(ProjectedColumnExpression.java:115)
>> at
>> org.apache.phoenix.schema.KeyValueSchema.toBytes(KeyValueSchema.java:112)
>> at
>> org.apache.phoenix.execute.TupleProjector.projectResults(TupleProjector.java:245)
>> at
>> org.apache.phoenix.coprocessor.BaseScannerRegionObserver$1.nextRaw(BaseScannerRegionObserver.java:441)
>> at
>> org.apache.phoenix.iterate.RegionScannerResultIterator.next(RegionScannerResultIterator.java:50)
>> ... 13 more
>> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
>> at
>> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
>> at
>> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
>> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
>> at
>> org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(RemoteExceptionHandler.java:97)
>> at
>> org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:272)
>> at
>> org.apache.hadoop.hbase.client.ScannerCallable.call(ScannerCallable.java:64)
>> at
>> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithoutRetries(RpcRetryingCaller.java:200)
>> at
>> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:360)
>> at
>> org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$RetryingRPC.call(ScannerCallableWithReplicas.java:334)
>> at
>> org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(RpcRetryingCaller.java:126)
>> at
>> org.apache.hadoop.hbase.client.ResultBoundedCompletionService$QueueingFuture.run(ResultBoundedCompletionService.java:65)
>> ... 3 more
>>
>> HBase Region Server Logs below,
>> 1.
>> 2017-07-05 04:33:41,181 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>> 2017-07-05 04:33:50,929 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 2.
>> 2017-07-05 04:32:52,087 INFO [sync.2] wal.FSHLog: Slow sync cost: 104
>> ms, current pipeline:
>>
>> [DatanodeInfoWithStorage[172.31.10.147:50010,DS-289c3237-9ec2-4abc-9fe8-e114fde75483,DISK],
>>
>> DatanodeInfoWithStorage[172.31.8.18:50010,DS-5887519a-6424-4bf9-9c09-35d9b13b5b1d,DISK],
>>
>> DatanodeInfoWithStorage[172.31.10.188:50010,DS-0c7f1e59-1719-4f5d-a400-79276b4469d1,DISK]]
>> 2017-07-05 04:34:31,791 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 3.
>> 2017-07-05 04:32:54,447 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.87 MB, cacheSize=1.87 MB, accesses=802,
>> hits=261, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=32.54%,
>> cachingAccesses=372, cachingHits=196, cachingHitsRatio=52.69%,
>> evictions=0, evicted=65, evictedPerRun=Infinity
>> 2017-07-05 04:34:18,621 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 4.
>> 2017-07-05 04:33:41,653 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>> 2017-07-05 04:33:50,601 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 5.
>> 2017-07-05 04:32:04,566 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.82 MB, cacheSize=1.85 MB, accesses=300,
>> hits=114, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=38.00%,
>> cachingAccesses=203, cachingHits=114, cachingHitsRatio=56.16%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:33:41,167 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 6.
>> 2017-07-05 04:31:52,910 INFO
>>
>> [ip-172-31-11-39.ap-northeast-1.compute.internal,16020,1499227300627-index-writer--pool30-t13]
>> regionserver.HRegion: writing data to region
>>
>> TRB,\x0C\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.f0fade12881d6c99e9674639c90acad1.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
>> GB, blockCount=2, accesses=49007, hits=49007, hitRatio=100.00%, ,
>> cachingAccesses=49007, cachingHits=49007, cachingHitsRatio=100.00%,
>> evictions=179, evicted=0, evictedPerRun=0.0
>> 2017-07-05 04:32:04,581 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=79.99 GB, usedSize=5.59 MB, cacheSize=3.66 MB, accesses=599,
>> hits=218, IOhitsPerSecond=0, IOTimePerHit=0.09, hitRatio=36.39%,
>> cachingAccesses=402, cachingHits=218, cachingHitsRatio=54.23%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:33:46,020 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 7.
>> 2017-07-05 04:31:53,027 INFO
>>
>> [ip-172-31-12-156.ap-northeast-1.compute.internal,16020,1499227465864-index-writer--pool26-t15]
>> regionserver.HRegion: writing data to region
>>
>> TRB,\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.31b5cfcc09891813241932c46e2e6d5b.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:34:10,233 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>> 2017-07-05 04:34:29,590 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
>> GB, blockCount=2, accesses=27170, hits=27170, hitRatio=100.00%, ,
>> cachingAccesses=27170, cachingHits=27170, cachingHitsRatio=100.00%,
>> evictions=179, evicted=0, evictedPerRun=0.0
>> 2017-07-05 04:34:29,643 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.90 MB, cacheSize=1.90 MB, accesses=295,
>> hits=98, IOhitsPerSecond=0, IOTimePerHit=NaN, hitRatio=33.22%,
>> cachingAccesses=200, cachingHits=98, cachingHitsRatio=49.00%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:35:13,274 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 8.
>> 2017-07-05 04:27:41,202 ERROR
>> [RpcServer.FifoWFPBQ.default.handler=29,queue=2,port=16020]
>> coprocessor.MetaDataEndpointImpl: getTable failed
>> org.apache.hadoop.hbase.NotServingRegionException:
>> SYSTEM.CATALOG,,1499216017494.3bbe2fb5b186285a9555b45c87684cc7. is
>> closing
>> at
>> org.apache.hadoop.hbase.regionserver.HRegion.startRegionOperation(HRegion.java:8291)
>> at
>> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2645)
>> at
>> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2640)
>> at
>> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2634)
>> at
>> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.buildTable(MetaDataEndpointImpl.java:533)
>> at
>> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2939)
>> at
>> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(MetaDataEndpointImpl.java:2884)
>> at
>> org.apache.phoenix.coprocessor.MetaDataEndpointImpl.getTable(MetaDataEndpointImpl.java:492)
>> at
>> org.apache.phoenix.coprocessor.generated.MetaDataProtos$MetaDataService.callMethod(MetaDataProtos.java:16267)
>> at
>> org.apache.hadoop.hbase.regionserver.HRegion.execService(HRegion.java:8095)
>> at
>> org.apache.hadoop.hbase.regionserver.RSRpcServices.execServiceOnRegion(RSRpcServices.java:2072)
>> at
>> org.apache.hadoop.hbase.regionserver.RSRpcServices.execService(RSRpcServices.java:2054)
>> at
>> org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34954)
>> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
>> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
>> at
>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:188)
>> at
>> org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(RpcExecutor.java:168)
>> 2017-07-05 04:31:53,017 INFO
>>
>> [ip-172-31-14-56.ap-northeast-1.compute.internal,16020,1499227310987-index-writer--pool43-t18]
>> regionserver.HRegion: writing data to region
>>
>> TRB,\x07\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.c93f2a12e912e9501f0801e9cb73f75c.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:32:04,571 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=3.01 MB, cacheSize=1.97 MB, accesses=1077,
>> hits=881, IOhitsPerSecond=0, IOTimePerHit=0.16, hitRatio=81.80%,
>> cachingAccesses=980, cachingHits=881, cachingHitsRatio=89.90%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:36:34,114 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 9.
>> 2017-07-05 04:31:52,915 INFO
>>
>> [ip-172-31-3-154.ap-northeast-1.compute.internal,16020,1499227309930-index-writer--pool3-t13]
>> regionserver.HRegion: writing data to region
>>
>> TRB,\x0D\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228749864.9eca4d9d19a712533aa240853173c816.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:32:04,506 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> GB, blockCount=4, accesses=26651, hits=26651, hitRatio=100.00%, ,
>> cachingAccesses=26651, cachingHits=26651, cachingHitsRatio=100.00%,
>> evictions=179, evicted=0, evictedPerRun=0.0
>> 2017-07-05 04:32:04,556 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.85 MB, cacheSize=1.85 MB, accesses=334,
>> hits=134, IOhitsPerSecond=0, IOTimePerHit=0.15, hitRatio=40.12%,
>> cachingAccesses=239, cachingHits=134, cachingHitsRatio=56.07%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:33:33,010 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>> 2017-07-05 04:33:40,823 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 10.
>> 2017-07-05 04:31:53,653 INFO
>>
>> [ip-172-31-7-66.ap-northeast-1.compute.internal,16020,1499227313375-index-writer--pool38-t18]
>> regionserver.HRegion: writing data to region
>>
>> TRP,\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.6706144c5be72f993a69ad9ad63005e5.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> GB, blockCount=1, accesses=24493, hits=24493, hitRatio=100.00%, ,
>> cachingAccesses=24493, cachingHits=24493, cachingHitsRatio=100.00%,
>> evictions=179, evicted=0, evictedPerRun=0.0
>> 2017-07-05 04:32:04,577 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.48 MB, cacheSize=1.62 MB, accesses=260,
>> hits=81, IOhitsPerSecond=0, IOTimePerHit=0.10, hitRatio=31.15%,
>> cachingAccesses=164, cachingHits=81, cachingHitsRatio=49.39%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:36:04,834 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> 11.
>> 2017-07-05 04:31:53,327 INFO
>>
>> [ip-172-31-8-18.ap-northeast-1.compute.internal,16020,1499227319500-index-writer--pool26-t18]
>> regionserver.HRegion: writing data to region
>>
>> TRP,\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,1499228698442.53d87d4772b4e637b4dfd426bb11d624.
>> with WAL disabled. Data may be lost in the event of a crash.
>> 2017-07-05 04:32:04,505 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
>> GB, blockCount=1, accesses=23309, hits=23309, hitRatio=100.00%, ,
>> cachingAccesses=23309, cachingHits=23309, cachingHitsRatio=100.00%,
>> evictions=179, evicted=0, evictedPerRun=0.0
>> 2017-07-05 04:32:04,574 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
>> freeSize=80.00 GB, usedSize=2.83 MB, cacheSize=1.85 MB, accesses=330,
>> hits=138, IOhitsPerSecond=0, IOTimePerHit=0.12, hitRatio=41.82%,
>> cachingAccesses=232, cachingHits=138, cachingHitsRatio=59.48%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-05 04:33:58,658 WARN [Finalizer] memory.GlobalMemoryManager:
>> Orphaned chunk of 104 bytes found during finalize
>>
>> The TRP table is mutable which have composite parimary key, and have 5
>> local indexes.
>> I always upsert data from phoenix only.
>>
>> Phoenix Configuration is below,
>> phoenix.schema.dropMetaData false
>> phoenix.query.rowKeyOrderSaltedTable true
>> hbase.regionserver.wal.codec
>> org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec
>> hbase.region.server.rpc.scheduler.factory.class
>> org.apache.hadoop.hbase.ipc.PhoenixRpcSchedulerFactory
>> phoenix.index.failure.block.write true
>>
>> How can i solve this?
>> Please advise me if you do not mind.
>>
>> Thanks,
>> Takashi
>
>
Re: Exception ERROR 201 (22000): Illegal data. Expected length of at
least 8 bytes, but had 4
Posted by Josh Mahonin <jm...@gmail.com>.
Hi,
From the logs you attached, it appears that you're getting the exception on
the following query:
SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
DESC NULLS LAST FETCH FIRST 1 ROW ONLY
Are you able to reproduce this issue by executing that query directly?
Given a snippet of your stack trace, I'm not sure if Spark is the culprit
here, so it'd be nice to try identify the root cause (or maybe correlate it
to an existing JIRA ticket)
...
Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
at least 8 bytes, but had 4
TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00,
1499228698442.4f312a19bfdc624776516228c9c4f2d5.
at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
newException(SQLExceptionCode.java:464)
at org.apache.phoenix.exception.SQLExceptionInfo.buildException(
SQLExceptionInfo.java:150)
at org.apache.phoenix.util.ServerUtil.parseRemoteException(
ServerUtil.java:134)
at org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
ServerUtil.java:123)
at org.apache.phoenix.util.ServerUtil.parseServerException(
ServerUtil.java:109)
at org.apache.phoenix.iterate.BaseResultIterators.getIterators(
BaseResultIterators.java:755)
at org.apache.phoenix.iterate.BaseResultIterators.getIterators(
BaseResultIterators.java:699)
at org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(
MergeSortResultIterator.java:72)
at org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(
MergeSortResultIterator.java:93)
at org.apache.phoenix.iterate.MergeSortResultIterator.next(
MergeSortResultIterator.java:58)
at org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(
MergeSortTopNResultIterator.java:95)
at org.apache.phoenix.jdbc.PhoenixResultSet.next(PhoenixResultSet.java:778)
...
Also, are you able to post your CREATE TABLE DDL for the 'trp' table you're
querying?
Thanks,
Josh
On Wed, Jul 5, 2017 at 1:24 AM, Takashi Sasaki <ts...@gmail.com> wrote:
> Hi,
>
> I'm using Phoenix4.9.0/HBase1.3.0 with Spark2.1.1 on AWS EMR 5.6.0.
>
> When one side uses Spark Streaming to write a lot of data and the
> other side uses Spark to read data,
> I encounter several similar exceptions.
>
> 17/07/05 04:33:47 ERROR Executor: Exception in task 83.0 in stage
> 166.0 (TID 95211)
> org.apache.ibatis.exceptions.PersistenceException:
> ### Error querying database. Cause: java.sql.SQLException: ERROR 201
> (22000): Illegal data. ERROR 201 (22000): ERROR 201 (22000): Illegal
> data. Expected length of at least 8 bytes, but had 4
> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> ### The error may exist in agp/mapper/TripMapper.java (best guess)
> ### The error may involve agp.mapper.TripMapper.selectLast
> ### The error occurred while handling results
> ### SQL: SELECT trid, tid, frtp, frno, gzid, ontm, onty, onlt, onln,
> oftm, ofty, oflt, ofln, onwk, onhr, wday, dist, drtn, delf, sntf,
> cdtm, udtm FROM trp WHERE tid = ? AND delf = FALSE ORDER BY oftm
> DESC NULLS LAST FETCH FIRST 1 ROW ONLY
> ### Cause: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> at least 8 bytes, but had 4
> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(
> ExceptionFactory.java:30)
> at org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:150)
> at org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:141)
> at org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectOne(DefaultSqlSession.java:77)
> at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:82)
> at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
> at com.sun.proxy.$Proxy38.selectLast(Unknown Source)
> at agp.dao.TripDAO.selectLast(TripDAO.java:55)
> at agp.trip.func.trip.SelectTripCondition.fixAccOnLocation(
> SelectTripCondition.java:128)
> at agp.trip.func.trip.SelectTripCondition.call(
> SelectTripCondition.java:65)
> at agp.trip.func.trip.SelectTripCondition.call(
> SelectTripCondition.java:25)
> at org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.
> apply(JavaRDDLike.scala:125)
> at org.apache.spark.api.java.JavaRDDLike$$anonfun$fn$1$1.
> apply(JavaRDDLike.scala:125)
> at scala.collection.Iterator$$anon$12.nextCur(Iterator.scala:434)
> at scala.collection.Iterator$$anon$12.hasNext(Iterator.scala:440)
> at scala.collection.Iterator$$anon$13.hasNext(Iterator.scala:461)
> at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:408)
> at org.apache.spark.shuffle.sort.UnsafeShuffleWriter.write(
> UnsafeShuffleWriter.java:166)
> at org.apache.spark.scheduler.ShuffleMapTask.runTask(
> ShuffleMapTask.scala:96)
> at org.apache.spark.scheduler.ShuffleMapTask.runTask(
> ShuffleMapTask.scala:53)
> at org.apache.spark.scheduler.Task.run(Task.scala:99)
> at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:322)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(
> ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> ERROR 201 (22000): ERROR 201 (22000): Illegal data. Expected length of
> at least 8 bytes, but had 4
> TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> at org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> at org.apache.phoenix.util.ServerUtil.parseRemoteException(
> ServerUtil.java:134)
> at org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
> ServerUtil.java:123)
> at org.apache.phoenix.util.ServerUtil.parseServerException(
> ServerUtil.java:109)
> at org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:755)
> at org.apache.phoenix.iterate.BaseResultIterators.getIterators(
> BaseResultIterators.java:699)
> at org.apache.phoenix.iterate.MergeSortResultIterator.getMinHeap(
> MergeSortResultIterator.java:72)
> at org.apache.phoenix.iterate.MergeSortResultIterator.minIterator(
> MergeSortResultIterator.java:93)
> at org.apache.phoenix.iterate.MergeSortResultIterator.next(
> MergeSortResultIterator.java:58)
> at org.apache.phoenix.iterate.MergeSortTopNResultIterator.next(
> MergeSortTopNResultIterator.java:95)
> at org.apache.phoenix.jdbc.PhoenixResultSet.next(
> PhoenixResultSet.java:778)
> at sun.reflect.GeneratedMethodAccessor37.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(
> DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(
> ResultSetLogger.java:68)
> at com.sun.proxy.$Proxy37.next(Unknown Source)
> at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:345)
> at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleRowValues(DefaultResultSetHandler.java:322)
> at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleResultSet(DefaultResultSetHandler.java:295)
> at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.
> handleResultSets(DefaultResultSetHandler.java:192)
> at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(
> PreparedStatementHandler.java:64)
> at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(
> RoutingStatementHandler.java:79)
> at org.apache.ibatis.executor.SimpleExecutor.doQuery(
> SimpleExecutor.java:63)
> at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(
> BaseExecutor.java:324)
> at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
> at org.apache.ibatis.executor.CachingExecutor.query(
> CachingExecutor.java:109)
> at org.apache.ibatis.executor.CachingExecutor.query(
> CachingExecutor.java:83)
> at org.apache.ibatis.session.defaults.DefaultSqlSession.
> selectList(DefaultSqlSession.java:148)
> ... 23 more
> Caused by: org.apache.hadoop.hbase.DoNotRetryIOException:
> org.apache.hadoop.hbase.DoNotRetryIOException: ERROR 201 (22000):
> ERROR 201 (22000): Illegal data. Expected length of at least 8 bytes,
> but had 4 TRP,\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.4f312a19bfdc624776516228c9c4f2d5.
> at org.apache.phoenix.util.ServerUtil.createIOException(
> ServerUtil.java:81)
> at org.apache.phoenix.util.ServerUtil.throwIOException(
> ServerUtil.java:55)
> at org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(
> ScanRegionObserver.java:328)
> at org.apache.phoenix.coprocessor.ScanRegionObserver.doPostScannerOpen(
> ScanRegionObserver.java:241)
> at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$
> RegionScannerHolder.overrideDelegate(BaseScannerRegionObserver.java:215)
> at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$
> RegionScannerHolder.nextRaw(BaseScannerRegionObserver.java:260)
> at org.apache.hadoop.hbase.regionserver.RSRpcServices.
> scan(RSRpcServices.java:2633)
> at org.apache.hadoop.hbase.regionserver.RSRpcServices.
> scan(RSRpcServices.java:2837)
> at org.apache.hadoop.hbase.protobuf.generated.
> ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34950)
> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
> at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:188)
> at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:168)
> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> Expected length of at least 8 bytes, but had 4
> at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> at org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> at org.apache.phoenix.util.ServerUtil.parseRemoteException(
> ServerUtil.java:134)
> at org.apache.phoenix.util.ServerUtil.parseServerExceptionOrNull(
> ServerUtil.java:123)
> at org.apache.phoenix.util.ServerUtil.parseServerException(
> ServerUtil.java:109)
> at org.apache.phoenix.iterate.RegionScannerResultIterator.next(
> RegionScannerResultIterator.java:61)
> at org.apache.phoenix.iterate.OrderedResultIterator.getResultIterator(
> OrderedResultIterator.java:254)
> at org.apache.phoenix.iterate.OrderedResultIterator.next(
> OrderedResultIterator.java:198)
> at org.apache.phoenix.coprocessor.ScanRegionObserver.getTopNScanner(
> ScanRegionObserver.java:323)
> ... 10 more
> Caused by: java.sql.SQLException: ERROR 201 (22000): Illegal data.
> Expected length of at least 8 bytes, but had 4
> at org.apache.phoenix.exception.SQLExceptionCode$Factory$1.
> newException(SQLExceptionCode.java:464)
> at org.apache.phoenix.exception.SQLExceptionInfo.buildException(
> SQLExceptionInfo.java:150)
> at org.apache.phoenix.schema.KeyValueSchema.next(KeyValueSchema.java:213)
> at org.apache.phoenix.expression.ProjectedColumnExpression.evaluate(
> ProjectedColumnExpression.java:115)
> at org.apache.phoenix.schema.KeyValueSchema.toBytes(
> KeyValueSchema.java:112)
> at org.apache.phoenix.execute.TupleProjector.projectResults(
> TupleProjector.java:245)
> at org.apache.phoenix.coprocessor.BaseScannerRegionObserver$1.nextRaw(
> BaseScannerRegionObserver.java:441)
> at org.apache.phoenix.iterate.RegionScannerResultIterator.next(
> RegionScannerResultIterator.java:50)
> ... 13 more
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(
> NativeConstructorAccessorImpl.java:62)
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(
> DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> at org.apache.hadoop.hbase.RemoteExceptionHandler.decodeRemoteException(
> RemoteExceptionHandler.java:97)
> at org.apache.hadoop.hbase.client.ScannerCallable.call(
> ScannerCallable.java:272)
> at org.apache.hadoop.hbase.client.ScannerCallable.call(
> ScannerCallable.java:64)
> at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithoutRetries(
> RpcRetryingCaller.java:200)
> at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$
> RetryingRPC.call(ScannerCallableWithReplicas.java:360)
> at org.apache.hadoop.hbase.client.ScannerCallableWithReplicas$
> RetryingRPC.call(ScannerCallableWithReplicas.java:334)
> at org.apache.hadoop.hbase.client.RpcRetryingCaller.callWithRetries(
> RpcRetryingCaller.java:126)
> at org.apache.hadoop.hbase.client.ResultBoundedCompletionService
> $QueueingFuture.run(ResultBoundedCompletionService.java:65)
> ... 3 more
>
> HBase Region Server Logs below,
> 1.
> 2017-07-05 04:33:41,181 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
> 2017-07-05 04:33:50,929 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 2.
> 2017-07-05 04:32:52,087 INFO [sync.2] wal.FSHLog: Slow sync cost: 104
> ms, current pipeline:
> [DatanodeInfoWithStorage[172.31.10.147:50010,DS-289c3237-
> 9ec2-4abc-9fe8-e114fde75483,DISK],
> DatanodeInfoWithStorage[172.31.8.18:50010,DS-5887519a-
> 6424-4bf9-9c09-35d9b13b5b1d,DISK],
> DatanodeInfoWithStorage[172.31.10.188:50010,DS-0c7f1e59-
> 1719-4f5d-a400-79276b4469d1,DISK]]
> 2017-07-05 04:34:31,791 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 3.
> 2017-07-05 04:32:54,447 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.87 MB, cacheSize=1.87 MB, accesses=802,
> hits=261, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=32.54%,
> cachingAccesses=372, cachingHits=196, cachingHitsRatio=52.69%,
> evictions=0, evicted=65, evictedPerRun=Infinity
> 2017-07-05 04:34:18,621 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 4.
> 2017-07-05 04:33:41,653 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
> 2017-07-05 04:33:50,601 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 5.
> 2017-07-05 04:32:04,566 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.82 MB, cacheSize=1.85 MB, accesses=300,
> hits=114, IOhitsPerSecond=0, IOTimePerHit=0.11, hitRatio=38.00%,
> cachingAccesses=203, cachingHits=114, cachingHitsRatio=56.16%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:33:41,167 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 6.
> 2017-07-05 04:31:52,910 INFO
> [ip-172-31-11-39.ap-northeast-1.compute.internal,16020,
> 1499227300627-index-writer--pool30-t13]
> regionserver.HRegion: writing data to region
> TRB,\x0C\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.f0fade12881d6c99e9674639c90acad1.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
> GB, blockCount=2, accesses=49007, hits=49007, hitRatio=100.00%, ,
> cachingAccesses=49007, cachingHits=49007, cachingHitsRatio=100.00%,
> evictions=179, evicted=0, evictedPerRun=0.0
> 2017-07-05 04:32:04,581 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=79.99 GB, usedSize=5.59 MB, cacheSize=3.66 MB, accesses=599,
> hits=218, IOhitsPerSecond=0, IOTimePerHit=0.09, hitRatio=36.39%,
> cachingAccesses=402, cachingHits=218, cachingHitsRatio=54.23%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:33:46,020 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 7.
> 2017-07-05 04:31:53,027 INFO
> [ip-172-31-12-156.ap-northeast-1.compute.internal,
> 16020,1499227465864-index-writer--pool26-t15]
> regionserver.HRegion: writing data to region
> TRB,\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.31b5cfcc09891813241932c46e2e6d5b.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:34:10,233 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
> 2017-07-05 04:34:29,590 INFO [LruBlockCacheStatsExecutor]
> hfile.LruBlockCache: totalSize=11.17 MB, freeSize=10.56 GB, max=10.57
> GB, blockCount=2, accesses=27170, hits=27170, hitRatio=100.00%, ,
> cachingAccesses=27170, cachingHits=27170, cachingHitsRatio=100.00%,
> evictions=179, evicted=0, evictedPerRun=0.0
> 2017-07-05 04:34:29,643 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.90 MB, cacheSize=1.90 MB, accesses=295,
> hits=98, IOhitsPerSecond=0, IOTimePerHit=NaN, hitRatio=33.22%,
> cachingAccesses=200, cachingHits=98, cachingHitsRatio=49.00%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:35:13,274 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 8.
> 2017-07-05 04:27:41,202 ERROR
> [RpcServer.FifoWFPBQ.default.handler=29,queue=2,port=16020]
> coprocessor.MetaDataEndpointImpl: getTable failed
> org.apache.hadoop.hbase.NotServingRegionException:
> SYSTEM.CATALOG,,1499216017494.3bbe2fb5b186285a9555b45c87684cc7. is
> closing
> at org.apache.hadoop.hbase.regionserver.HRegion.
> startRegionOperation(HRegion.java:8291)
> at org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2645)
> at org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2640)
> at org.apache.hadoop.hbase.regionserver.HRegion.
> getScanner(HRegion.java:2634)
> at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.buildTable(
> MetaDataEndpointImpl.java:533)
> at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(
> MetaDataEndpointImpl.java:2939)
> at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.doGetTable(
> MetaDataEndpointImpl.java:2884)
> at org.apache.phoenix.coprocessor.MetaDataEndpointImpl.getTable(
> MetaDataEndpointImpl.java:492)
> at org.apache.phoenix.coprocessor.generated.MetaDataProtos$
> MetaDataService.callMethod(MetaDataProtos.java:16267)
> at org.apache.hadoop.hbase.regionserver.HRegion.
> execService(HRegion.java:8095)
> at org.apache.hadoop.hbase.regionserver.RSRpcServices.
> execServiceOnRegion(RSRpcServices.java:2072)
> at org.apache.hadoop.hbase.regionserver.RSRpcServices.
> execService(RSRpcServices.java:2054)
> at org.apache.hadoop.hbase.protobuf.generated.
> ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:34954)
> at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2339)
> at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:123)
> at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:188)
> at org.apache.hadoop.hbase.ipc.RpcExecutor$Handler.run(
> RpcExecutor.java:168)
> 2017-07-05 04:31:53,017 INFO
> [ip-172-31-14-56.ap-northeast-1.compute.internal,16020,
> 1499227310987-index-writer--pool43-t18]
> regionserver.HRegion: writing data to region
> TRB,\x07\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.c93f2a12e912e9501f0801e9cb73f75c.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:32:04,571 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=3.01 MB, cacheSize=1.97 MB, accesses=1077,
> hits=881, IOhitsPerSecond=0, IOTimePerHit=0.16, hitRatio=81.80%,
> cachingAccesses=980, cachingHits=881, cachingHitsRatio=89.90%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:36:34,114 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 9.
> 2017-07-05 04:31:52,915 INFO
> [ip-172-31-3-154.ap-northeast-1.compute.internal,16020,
> 1499227309930-index-writer--pool3-t13]
> regionserver.HRegion: writing data to region
> TRB,\x0D\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00,1499228749864.9eca4d9d19a712533aa240853173c816.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:32:04,506 INFO [LruBlockCacheStatsExecutor]
> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> GB, blockCount=4, accesses=26651, hits=26651, hitRatio=100.00%, ,
> cachingAccesses=26651, cachingHits=26651, cachingHitsRatio=100.00%,
> evictions=179, evicted=0, evictedPerRun=0.0
> 2017-07-05 04:32:04,556 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.85 MB, cacheSize=1.85 MB, accesses=334,
> hits=134, IOhitsPerSecond=0, IOTimePerHit=0.15, hitRatio=40.12%,
> cachingAccesses=239, cachingHits=134, cachingHitsRatio=56.07%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:33:33,010 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
> 2017-07-05 04:33:40,823 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 10.
> 2017-07-05 04:31:53,653 INFO
> [ip-172-31-7-66.ap-northeast-1.compute.internal,16020,
> 1499227313375-index-writer--pool38-t18]
> regionserver.HRegion: writing data to region
> TRP,\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.6706144c5be72f993a69ad9ad63005e5.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:32:04,504 INFO [LruBlockCacheStatsExecutor]
> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> GB, blockCount=1, accesses=24493, hits=24493, hitRatio=100.00%, ,
> cachingAccesses=24493, cachingHits=24493, cachingHitsRatio=100.00%,
> evictions=179, evicted=0, evictedPerRun=0.0
> 2017-07-05 04:32:04,577 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.48 MB, cacheSize=1.62 MB, accesses=260,
> hits=81, IOhitsPerSecond=0, IOTimePerHit=0.10, hitRatio=31.15%,
> cachingAccesses=164, cachingHits=81, cachingHitsRatio=49.39%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:36:04,834 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> 11.
> 2017-07-05 04:31:53,327 INFO
> [ip-172-31-8-18.ap-northeast-1.compute.internal,16020,
> 1499227319500-index-writer--pool26-t18]
> regionserver.HRegion: writing data to region
> TRP,\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\
> x00\x00\x00\x00\x00,1499228698442.53d87d4772b4e637b4dfd426bb11d624.
> with WAL disabled. Data may be lost in the event of a crash.
> 2017-07-05 04:32:04,505 INFO [LruBlockCacheStatsExecutor]
> hfile.LruBlockCache: totalSize=11.14 MB, freeSize=10.56 GB, max=10.57
> GB, blockCount=1, accesses=23309, hits=23309, hitRatio=100.00%, ,
> cachingAccesses=23309, cachingHits=23309, cachingHitsRatio=100.00%,
> evictions=179, evicted=0, evictedPerRun=0.0
> 2017-07-05 04:32:04,574 INFO [BucketCacheStatsExecutor]
> bucket.BucketCache: failedBlockAdditions=0, totalSize=80.00 GB,
> freeSize=80.00 GB, usedSize=2.83 MB, cacheSize=1.85 MB, accesses=330,
> hits=138, IOhitsPerSecond=0, IOTimePerHit=0.12, hitRatio=41.82%,
> cachingAccesses=232, cachingHits=138, cachingHitsRatio=59.48%,
> evictions=0, evicted=0, evictedPerRun=NaN
> 2017-07-05 04:33:58,658 WARN [Finalizer] memory.GlobalMemoryManager:
> Orphaned chunk of 104 bytes found during finalize
>
> The TRP table is mutable which have composite parimary key, and have 5
> local indexes.
> I always upsert data from phoenix only.
>
> Phoenix Configuration is below,
> phoenix.schema.dropMetaData false
> phoenix.query.rowKeyOrderSaltedTable true
> hbase.regionserver.wal.codec
> org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec
> hbase.region.server.rpc.scheduler.factory.class
> org.apache.hadoop.hbase.ipc.PhoenixRpcSchedulerFactory
> phoenix.index.failure.block.write true
>
> How can i solve this?
> Please advise me if you do not mind.
>
> Thanks,
> Takashi
>