Thanks for the pointers Aaron. We checked hdfs. Its reporting 0
underreplicated or corrupted blocks.
@Ted: we are using Hadoop 2.7.3(EMR5.7.2)
On Thu, Jul 6, 2017 at 4:49 PM, Ted Yu <yuzhih...@gmail.com> wrote:
> Which hadoop release are you using ?
>
> In FSOutputSummer.java, I see the following around line 106:
>
> checkClosed();
>
> if (off < 0 || len < 0 || off > b.length - len) {
> throw new ArrayIndexOutOfBoundsException();
>
> You didn't get ArrayIndexOutOfBoundsException - maybe b was null ?
>
> On Thu, Jul 6, 2017 at 2:08 PM, anil gupta <anilgupt...@gmail.com> wrote:
>
>> Hey Ted,
>>
>> This is what i see in one of region server log(NPE at the bottom):
>> 2017-07-06 19:07:07,778 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 155739ms
>> 2017-07-06 19:07:17,853 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 132731ms
>> 2017-07-06 19:07:28,038 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 4316ms
>> 2017-07-06 19:07:37,819 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 190960ms
>> 2017-07-06 19:07:47,767 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 41231ms
>> 2017-07-06 19:07:57,767 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 222748ms
>> 2017-07-06 19:08:07,973 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 245966ms
>> 2017-07-06 19:08:18,669 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 76257ms
>> 2017-07-06 19:08:28,029 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 78310ms
>> 2017-07-06 19:08:38,459 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 127828ms
>> 2017-07-06 19:08:48,527 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 38647ms
>> 2017-07-06 19:08:58,554 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 185493ms
>> 2017-07-06 19:09:07,779 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 245608ms
>> 2017-07-06 19:09:17,767 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 284400ms
>> 2017-07-06 19:09:27,768 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 271921ms
>> 2017-07-06 19:09:38,380 INFO
>> [ip-10-74-5-153.us-west-2.compute.internal,16020,14993202605
>> 01_ChoreService_1]
>> regionserver.HRegionServer:
>> ip-10-74-5-153.us-west-2.compute.internal,16020,149932026050
>> 1-MemstoreFlusherChore
>> requesting flush of
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. because 0
>> has an old edit so flush to free WALs after random delay 205397ms
>> 2017-07-06 19:09:43,518 INFO [MemStoreFlusher.1] regionserver.HRegion:
>> Flushing 1/1 column families, memstore=102.57 KB
>> 2017-07-06 19:09:43,541 INFO [MemStoreFlusher.1]
>> regionserver.DefaultStoreFlusher: Flushed, sequenceid=163, memsize=102.6
>> K,
>> hasBloomFilter=true, into tmp file
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/data/default/SYSTEM.CATALOG/a47ffa359aa4588f5f3607
>> 90ac8e4561/.tmp/80386bf477b648d1a7edbbb271601e96
>> 2017-07-06 19:09:43,546 INFO [MemStoreFlusher.1]
>> regionserver.StoreFile$Reader: Loaded Delete Family Bloom
>> (CompoundBloomFilter) metadata for 80386bf477b648d1a7edbbb271601e96
>> 2017-07-06 19:09:43,552 INFO [MemStoreFlusher.1]
>> regionserver.StoreFile$Reader: Loaded Delete Family Bloom
>> (CompoundBloomFilter) metadata for 80386bf477b648d1a7edbbb271601e96
>> 2017-07-06 19:09:43,552 INFO [MemStoreFlusher.1] regionserver.HStore:
>> Added
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/data/default/SYSTEM.CATALOG/a47ffa359aa4588f5f3607
>> 90ac8e4561/0/80386bf477b648d1a7edbbb271601e96,
>> entries=552, sequenceid=163, filesize=11.4 K
>> 2017-07-06 19:09:43,553 INFO [MemStoreFlusher.1] regionserver.HRegion:
>> Finished memstore flush of ~102.57 KB/105030, currentsize=0 B/0 for region
>> SYSTEM.CATALOG,,1499317930655.a47ffa359aa4588f5f360790ac8e4561. in 35ms,
>> sequenceid=163, compaction requested=false
>> 2017-07-06 19:11:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4799, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:11:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=65019,
>> hits=64759, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.60%,
>> cachingAccesses=65019, cachingHits=64759, cachingHitsRatio=99.60%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:11:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:11:25,156 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:11:25,156 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:11:25,656 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:11:25,657 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:11:25,659 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:11:25,659 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:16:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4829, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:16:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=65379,
>> hits=65119, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.60%,
>> cachingAccesses=65379, cachingHits=65119, cachingHitsRatio=99.60%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:16:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:16:25,158 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:16:25,158 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:16:25,658 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:16:25,661 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:16:25,662 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:16:25,662 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:21:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4859, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:21:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=65739,
>> hits=65479, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.60%,
>> cachingAccesses=65739, cachingHits=65479, cachingHitsRatio=99.60%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:21:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:21:25,156 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:21:25,156 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:21:25,656 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:21:25,658 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:21:25,660 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:21:25,660 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:26:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4889, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:26:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=66099,
>> hits=65839, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.61%,
>> cachingAccesses=66099, cachingHits=65839, cachingHitsRatio=99.61%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:26:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:26:25,158 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:26:25,158 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:26:25,659 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:26:25,660 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:26:25,663 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:26:25,663 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:31:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4919, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:31:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=66459,
>> hits=66199, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.61%,
>> cachingAccesses=66459, cachingHits=66199, cachingHitsRatio=99.61%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:31:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:31:25,158 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:31:25,158 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:31:25,659 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:31:25,660 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:31:25,661 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:31:25,661 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:31:40,742 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Rolled WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499365900659
>> with entries=8, filesize=12.99 KB; new WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499369500724
>> 2017-07-06 19:31:40,742 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Archiving
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,16020,
>> 1499320260501/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499362300596
>> to
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/oldWALs/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499362300596
>> 2017-07-06 19:31:40,745 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Archiving
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,16020,
>> 1499320260501/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499365900659
>> to
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/oldWALs/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499365900659
>> 2017-07-06 19:36:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4949, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:36:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=66819,
>> hits=66559, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.61%,
>> cachingAccesses=66819, cachingHits=66559, cachingHitsRatio=99.61%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:36:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:36:25,158 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:36:25,158 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:36:25,659 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:36:25,661 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:36:25,663 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:36:25,663 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:41:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=4979, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:41:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=67179,
>> hits=66919, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.61%,
>> cachingAccesses=67179, cachingHits=66919, cachingHitsRatio=99.61%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:41:25,155 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:41:25,156 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:41:25,156 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:41:25,657 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:41:25,658 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:41:25,660 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:41:25,660 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:46:02,141 INFO [LruBlockCacheStatsExecutor]
>> hfile.LruBlockCache: totalSize=4.93 MB, freeSize=4.67 GB, max=4.67 GB,
>> blockCount=2, accesses=14931, hits=14931, hitRatio=100.00%, ,
>> cachingAccesses=14931, cachingHits=14931, cachingHitsRatio=100.00%,
>> evictions=5009, evicted=0, evictedPerRun=0.0
>> 2017-07-06 19:46:07,418 INFO [BucketCacheStatsExecutor]
>> bucket.BucketCache: failedBlockAdditions=0, totalSize=11.75 GB,
>> freeSize=11.74 GB, usedSize=8.18 MB, cacheSize=7.29 MB, accesses=67539,
>> hits=67279, IOhitsPerSecond=1, IOTimePerHit=0.00, hitRatio=99.62%,
>> cachingAccesses=67539, cachingHits=67279, cachingHitsRatio=99.62%,
>> evictions=0, evicted=0, evictedPerRun=NaN
>> 2017-07-06 19:46:25,156 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Stopping HBase metrics system...
>> 2017-07-06 19:46:25,158 INFO [ganglia] impl.MetricsSinkAdapter: ganglia
>> thread interrupted.
>> 2017-07-06 19:46:25,158 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system stopped.
>> 2017-07-06 19:46:25,659 INFO [HBase-Metrics2-1] impl.MetricsConfig:
>> loaded
>> properties from hadoop-metrics2-hbase.properties
>> 2017-07-06 19:46:25,660 INFO [HBase-Metrics2-1] impl.MetricsSinkAdapter:
>> Sink ganglia started
>> 2017-07-06 19:46:25,662 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> Scheduled snapshot period at 155 second(s).
>> 2017-07-06 19:46:25,662 INFO [HBase-Metrics2-1] impl.MetricsSystemImpl:
>> HBase metrics system started
>> 2017-07-06 19:48:30,412 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x3da2857f
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:30,412 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x3da2857f0x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:30,414 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:30,414 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:30,415 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd2, negotiated timeout = 40000
>> 2017-07-06 19:48:30,426 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd2
>> 2017-07-06 19:48:30,427 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd2 closed
>> 2017-07-06 19:48:30,427 INFO
>> [B.defaultRpcServer.handler=175,queue=15,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd2
>> 2017-07-06 19:48:30,483 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x41f2d6a0
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:30,483 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x41f2d6a00x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:30,484 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020-SendThread
>> (ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:30,485 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020-SendThread
>> (ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:30,486 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020-SendThread
>> (ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd3, negotiated timeout = 40000
>> 2017-07-06 19:48:30,493 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd3
>> 2017-07-06 19:48:30,493 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd3 closed
>> 2017-07-06 19:48:30,493 INFO
>> [B.defaultRpcServer.handler=64,queue=4,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd3
>> 2017-07-06 19:48:30,520 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x2765c233
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:30,520 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x2765c2330x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:30,522 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:30,523 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:30,524 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd4, negotiated timeout = 40000
>> 2017-07-06 19:48:30,529 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd4
>> 2017-07-06 19:48:30,530 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd4 closed
>> 2017-07-06 19:48:30,530 INFO
>> [B.defaultRpcServer.handler=53,queue=13,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd4
>> 2017-07-06 19:48:30,558 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x31d0fcd8
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:30,558 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x31d0fcd80x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:30,559 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:30,559 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:30,560 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd5, negotiated timeout = 40000
>> 2017-07-06 19:48:30,565 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd5
>> 2017-07-06 19:48:30,566 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd5 closed
>> 2017-07-06 19:48:30,566 INFO
>> [B.defaultRpcServer.handler=112,queue=12,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd5
>> 2017-07-06 19:48:30,594 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x336d2534
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:30,594 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x336d25340x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:30,596 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:30,596 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:30,597 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020-SendThrea
>> d(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd6, negotiated timeout = 40000
>> 2017-07-06 19:48:30,603 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd6
>> 2017-07-06 19:48:30,604 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd6 closed
>> 2017-07-06 19:48:30,604 INFO
>> [B.defaultRpcServer.handler=12,queue=12,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd6
>> 2017-07-06 19:48:36,166 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7afe923b
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:36,166 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x7afe923b0x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:36,167 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:36,168 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:36,168 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd8, negotiated timeout = 40000
>> 2017-07-06 19:48:36,179 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd8
>> 2017-07-06 19:48:36,180 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd8 closed
>> 2017-07-06 19:48:36,180 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd8
>> 2017-07-06 19:48:36,191 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x553c739a
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:36,191 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x553c739a0x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:36,193 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:36,194 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:36,195 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cd9, negotiated timeout = 40000
>> 2017-07-06 19:48:36,202 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cd9
>> 2017-07-06 19:48:36,203 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cd9 closed
>> 2017-07-06 19:48:36,203 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cd9
>> 2017-07-06 19:48:36,214 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x7f2df76f
>> connecting to ZooKeeper
>> ensemble=ip-10-74-31-169.us-west-2.compute.internal:2181
>> 2017-07-06 19:48:36,214 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Initiating client connection,
>> connectString=ip-10-74-31-169.us-west-2.compute.internal:2181
>> sessionTimeout=90000 watcher=hconnection-0x7f2df76f0x0,
>> quorum=ip-10-74-31-169.us-west-2.compute.internal:2181, baseZNode=/hbase
>> 2017-07-06 19:48:36,215 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Opening socket connection to server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181. Will not
>> attempt to authenticate using SASL (unknown error)
>> 2017-07-06 19:48:36,216 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Socket connection established to
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, initiating
>> session
>> 2017-07-06 19:48:36,216 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-SendThre
>> ad(ip-10-74-31-169.us-west-2.compute.internal:2181)]
>> zookeeper.ClientCnxn: Session establishment complete on server
>> ip-10-74-31-169.us-west-2.compute.internal/10.74.31.169:2181, sessionid =
>> 0x15d150266d00cda, negotiated timeout = 40000
>> 2017-07-06 19:48:36,222 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020]
>> client.ConnectionManager$HConnectionImplementation: Closing zookeeper
>> sessionid=0x15d150266d00cda
>> 2017-07-06 19:48:36,222 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020] zookeeper.ZooKeeper:
>> Session: 0x15d150266d00cda closed
>> 2017-07-06 19:48:36,225 INFO
>> [B.defaultRpcServer.handler=172,queue=12,port=16020-EventThread]
>> zookeeper.ClientCnxn: EventThread shut down for session: 0x15d150266d00cda
>> 2017-07-06 19:48:38,085 WARN
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.append-pool1-t1]
>> wal.FSHLog: Append sequenceId=7845, requesting roll of WAL
>> java.lang.NullPointerException
>> at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:106)
>> at
>> org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(
>> FSDataOutputStream.java:60)
>> at java.io.DataOutputStream.write(DataOutputStream.java:107)
>> at org.apache.hadoop.hbase.KeyValue.oswrite(KeyValue.java:2571)
>> at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.
>> java:623)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$Ensure
>> KvEncoder.write(WALCellCodec.java:338)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.
>> append(ProtobufLogWriter.java:122)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.append(FSHLog.java:1909)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1773)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1695)
>> at
>> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
>> at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
>> Executor.java:1142)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
>> lExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>> 2017-07-06 19:48:38,097 WARN
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Failed sync-before-close but no outstanding appends; closing
>> WAL: org.apache.hadoop.hbase.regionserver.wal.DamagedWALException: Append
>> sequenceId=7845, requesting roll of WAL
>> 2017-07-06 19:48:38,102 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Rolled WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499369500724
>> with entries=0, filesize=174 B; new WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499370518086
>> 2017-07-06 19:48:38,102 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Archiving
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,16020,
>> 1499320260501/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499369500724
>> to
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/oldWALs/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499369500724
>> 2017-07-06 19:48:39,235 WARN
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.append-pool1-t1]
>> wal.FSHLog: Append sequenceId=7846, requesting roll of WAL
>> java.lang.NullPointerException
>> at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:106)
>> at
>> org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(
>> FSDataOutputStream.java:60)
>> at java.io.DataOutputStream.write(DataOutputStream.java:107)
>> at org.apache.hadoop.hbase.KeyValue.oswrite(KeyValue.java:2571)
>> at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.
>> java:623)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$Ensure
>> KvEncoder.write(WALCellCodec.java:338)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.
>> append(ProtobufLogWriter.java:122)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.append(FSHLog.java:1909)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1773)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1695)
>> at
>> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
>> at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
>> Executor.java:1142)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
>> lExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>> 2017-07-06 19:48:39,255 WARN
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Failed sync-before-close but no outstanding appends; closing
>> WAL: org.apache.hadoop.hbase.regionserver.wal.DamagedWALException: Append
>> sequenceId=7846, requesting roll of WAL
>> 2017-07-06 19:48:39,261 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Rolled WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499370518086
>> with entries=0, filesize=174 B; new WAL
>> /user/hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,
>> 16020,1499320260501/ip-10-74-5-153.us-west-2.compute.
>> internal%2C16020%2C1499320260501.default.1499370519235
>> 2017-07-06 19:48:39,261 INFO
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.logRoller]
>> wal.FSHLog: Archiving
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/WALs/ip-10-74-5-153.us-west-2.compute.internal,16020,
>> 1499320260501/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499370518086
>> to
>> hdfs://ip-10-74-31-169.us-west-2.compute.internal:8020/user/
>> hbase/oldWALs/ip-10-74-5-153.us-west-2.compute.internal%
>> 2C16020%2C1499320260501.default.1499370518086
>> 2017-07-06 19:48:40,322 WARN
>> [regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.7
>> 4.5.153:16020.append-pool1-t1]
>> wal.FSHLog: Append sequenceId=7847, requesting roll of WAL
>> java.lang.NullPointerException
>> at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:106)
>> at
>> org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(
>> FSDataOutputStream.java:60)
>> at java.io.DataOutputStream.write(DataOutputStream.java:107)
>> at org.apache.hadoop.hbase.KeyValue.oswrite(KeyValue.java:2571)
>> at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.
>> java:623)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$Ensure
>> KvEncoder.write(WALCellCodec.java:338)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.
>> append(ProtobufLogWriter.java:122)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.append(FSHLog.java:1909)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1773)
>> at
>> org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEv
>> entHandler.onEvent(FSHLog.java:1695)
>> at
>> com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:128)
>> at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
>> Executor.java:1142)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
>> lExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>>
>> On Thu, Jul 6, 2017 at 1:55 PM, Ted Yu <yuzhih...@gmail.com> wrote:
>>
>> > HBASE-16960 mentioned the following :
>> >
>> > Caused by: java.net.SocketTimeoutException: 20000 millis timeout while
>> > waiting for channel to be ready for read
>> >
>> > Do you see similar line in region server log ?
>> >
>> > Cheers
>> >
>> > On Thu, Jul 6, 2017 at 1:48 PM, anil gupta <anilgupt...@gmail.com>
>> wrote:
>> >
>> > > Hi All,
>> > >
>> > > We are running HBase/Phoenix on EMR5.2(HBase1.2.3 and Phoenix4.7) and
>> we
>> > running into following exception when we are trying to load data into
>> one
>> > of our Phoenix table:
>> > > 2017-07-06 19:57:57,507 INFO [hconnection-0x60e5272-shared-
>> -pool2-t249]
>> > org.apache.hadoop.hbase.client.AsyncProcess: #1, table=DE.CONFIG_DATA,
>> > attempt=30/35 failed=38ops, last exception: org.apache.hadoop.hbase.
>> > regionserver.wal.DamagedWALException: org.apache.hadoop.hbase.
>> > regionserver.wal.DamagedWALException: Append sequenceId=8689,
>> requesting
>> > roll of WAL
>> > > at org.apache.hadoop.hbase.regionserver.wal.FSHLog$
>> > RingBufferEventHandler.append(FSHLog.java:1921)
>> > > at org.apache.hadoop.hbase.regionserver.wal.FSHLog$
>> > RingBufferEventHandler.onEvent(FSHLog.java:1773)
>> > > at org.apache.hadoop.hbase.regionserver.wal.FSHLog$
>> > RingBufferEventHandler.onEvent(FSHLog.java:1695)
>> > > at com.lmax.disruptor.BatchEventProcessor.run(
>> > BatchEventProcessor.java:128)
>> > > 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:745)
>> > >
>> > > We are OK with wiping out this table and rebuilding the dataset. We
>> > tried to drop the table and recreate the table but it didnt fix it.
>> > > Can anyone please let us know how can we get rid of above problem? Are
>> > we running into https://issues.apache.org/jira/browse/HBASE-16960?
>> > >
>> > >
>> > > --
>> > > Thanks & Regards,
>> > > Anil Gupta
>> > >
>> >
>>
>>
>>
>> --
>> Thanks & Regards,
>> Anil Gupta
>>
>
>
--
Thanks & Regards,
Anil Gupta
