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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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,1499320260501_ChoreService_1]
regionserver.HRegionServer:
ip-10-74-5-153.us-west-2.compute.internal,16020,1499320260501-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/a47ffa359aa4588f5f360790ac8e4561/.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/a47ffa359aa4588f5f360790ac8e4561/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.74.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.74.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.74.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-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,414 INFO
[B.defaultRpcServer.handler=175,queue=15,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,415 INFO
[B.defaultRpcServer.handler=175,queue=15,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 =
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-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,523 INFO
[B.defaultRpcServer.handler=53,queue=13,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,524 INFO
[B.defaultRpcServer.handler=53,queue=13,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 =
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-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,559 INFO
[B.defaultRpcServer.handler=112,queue=12,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,560 INFO
[B.defaultRpcServer.handler=112,queue=12,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 =
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-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,596 INFO
[B.defaultRpcServer.handler=12,queue=12,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,597 INFO
[B.defaultRpcServer.handler=12,queue=12,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 =
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-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:36,168 INFO
[B.defaultRpcServer.handler=172,queue=12,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:36,168 INFO
[B.defaultRpcServer.handler=172,queue=12,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 =
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-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:36,194 INFO
[B.defaultRpcServer.handler=172,queue=12,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:36,195 INFO
[B.defaultRpcServer.handler=172,queue=12,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 =
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-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:36,216 INFO
[B.defaultRpcServer.handler=172,queue=12,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:36,216 INFO
[B.defaultRpcServer.handler=172,queue=12,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 =
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.74.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$EnsureKvEncoder.write(WALCellCodec.java:338)
at
org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:122)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.append(FSHLog.java:1909)
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)
2017-07-06 19:48:38,097 WARN
[regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.74.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.74.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.74.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.74.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$EnsureKvEncoder.write(WALCellCodec.java:338)
at
org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:122)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.append(FSHLog.java:1909)
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)
2017-07-06 19:48:39,255 WARN
[regionserver/ip-10-74-5-153.us-west-2.compute.internal/10.74.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.74.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.74.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.74.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$EnsureKvEncoder.write(WALCellCodec.java:338)
at
org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:122)
at
org.apache.hadoop.hbase.regionserver.wal.FSHLog$RingBufferEventHandler.append(FSHLog.java:1909)
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)
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
