Hi all, I saw temporal high cpu usage of hbase, and having trouble to find its reason. Super long but ambiguous INFOs and WARNs are shown. I just guess that gc and heavy scan occurred at that time. 😞 2017-05-15 17:10:21,178 INFO [B.fifo.QRpcServer.handler=8,queue=2,port=16020] shortcircuit.ShortCircuitCache: ShortCircuitCache(0x1f8da901): could not load 1077622016_BP-1164966310-10.20.173.233-1472808503162 due to InvalidToken exception.
org.apache.hadoop.security.token.SecretManager$InvalidToken: access control error while attempting to set up short-circuit access to /apps/hbase/data/data/default/CMT_KWD_ANLY/3ae8d49c9f6652bc74f98fc14627f253/0/520be239596b4c0bbccceade5a837d89
at org.apache.hadoop.hdfs.BlockReaderFactory.requestFileDescriptors(BlockReaderFactory.java:589)
at org.apache.hadoop.hdfs.BlockReaderFactory.createShortCircuitReplicaInfo(BlockReaderFactory.java:488)
at org.apache.hadoop.hdfs.shortcircuit.ShortCircuitCache.create(ShortCircuitCache.java:784)
at org.apache.hadoop.hdfs.shortcircuit.ShortCircuitCache.fetchOrCreate(ShortCircuitCache.java:718)
at org.apache.hadoop.hdfs.BlockReaderFactory.getBlockReaderLocal(BlockReaderFactory.java:422)
at org.apache.hadoop.hdfs.BlockReaderFactory.build(BlockReaderFactory.java:333)
at org.apache.hadoop.hdfs.DFSInputStream.actualGetFromOneDataNode(DFSInputStream.java:1181)
at org.apache.hadoop.hdfs.DFSInputStream.fetchBlockByteRange(DFSInputStream.java:1118)
at org.apache.hadoop.hdfs.DFSInputStream.pread(DFSInputStream.java:1478)
at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:1441)
at org.apache.hadoop.fs.FSDataInputStream.read(FSDataInputStream.java:92)
at org.apache.hadoop.hbase.io.hfile.HFileBlock.positionalReadWithExtra(HFileBlock.java:722)
at org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1420)
at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockDataInternal(HFileBlock.java:1625)
at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockData(HFileBlock.java:1504)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:439)
at org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.loadDataBlockWithScanInfo(HFileBlockIndex.java:269)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$AbstractScannerV2.seekTo(HFileReaderV2.java:636)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$AbstractScannerV2.seekTo(HFileReaderV2.java:586)
at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:260)
at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:169)
at org.apache.hadoop.hbase.regionserver.StoreScanner.seekScanners(StoreScanner.java:363)
at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:217)
at org.apache.hadoop.hbase.regionserver.HStore.createScanner(HStore.java:2122)
at org.apache.hadoop.hbase.regionserver.HStore.getScanner(HStore.java:2112)
at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:5568)
at org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:2626)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2612)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2594)
at org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2280)
at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:32295)
at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2127)
at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:107)
at org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:133)
at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:108)
at java.lang.Thread.run(Thread.java:745)
2017-05-15 17:10:21,178 INFO [B.fifo.QRpcServer.handler=8,queue=2,port=16020] hdfs.DFSClient: Access token was invalid when connecting to /10.20.175.28:50010 : org.apache.hadoop.security.token.SecretManager$InvalidToken: access control error while attempting to set up short-circuit access to /apps/hbase/data/data/default/CMT_KWD_ANLY/3ae8d49c9f6652bc74f98fc14627f253/0/520be239596b4c0bbccceade5a837d89
2017-05-15 17:10:26,951 INFO [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 2497ms
GC pool 'ParNew' had collection(s): count=1 time=23ms
2017-05-15 17:10:31,954 [B.fifo.QRpcServer.handler=20,queue=2,port=16020] ipc.RpcServer: (responseTooSlow): {"call":"Scan(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ScanRequest)","starttimems":1494835821154,"responsesize":10,"method":"Scan","processingtimems":10800,"client":my_ip_and_port,"queuetimems":0,"class":"HRegionServer"}
I think JVM pause INFO is the most meaningful one but still not positive, because its duration is too short than the high cpu time. Thanks in advance!
... View more
