[jira] [Resolved] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng resolved HBASE-16212. - Resolution: Not A Bug > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Attachment: (was: regionserver-dfsinputstream.log) > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15385485#comment-15385485 ] Zhihua Deng commented on HBASE-16212: - Test on master branch, shows that the problem is rare so far. and Thanks [~stack]! > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: Test on master branch, shows that the problem is rare. Thanks [~stack]!) > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15385463#comment-15385463 ] Zhihua Deng commented on HBASE-16212: - Test on master branch, shows that the problem is rare. Thanks [~stack]! > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383514#comment-15383514 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 6:39 AM: -- Thanks [~stack]. From the logging, it implies that different threads share the same DFSInputStream instance, say 'defaultRpcServer.handler=7'(handler7) and 'defaultRpcServer.handler=4'(handler4), for example. The original will prefect the next block header and cache the header into thread. When defaultRpcServer.handler=4 comes, it first checks that the cached header offset is equal to the the block starting offset, unfortunately these two numbers are unequal(-1 != offset). The handler4 knows nothing about the block header, though the header has been prefected by handler7. The handler4 needs to seek the inputstream with the block starting offset for the header, while the inputstream has been over read by 33 bytes(the header size). So a new connection to datanode should be recreated, the elder one will be closed. When the datanode writes to a closed channel, a socket exception will be raised. When the same case happens frequently, the datanode will be suffered from logging the message described as it is. was (Author: dengzh): Thanks [~stack]. From the logging, it implies that different threads share the same DFSInputStream instance, say 'defaultRpcServer.handler=7'(handler7) and 'defaultRpcServer.handler=4'(handler4), for example. The original will prefect the next block header and cache the header into thread. When defaultRpcServer.handler=4 comes, it first checks that the cached header offset is equal to the the block starting offset, unfortunately these two numbers are unequal(-1 != offset). The handler4 knows nothing about the block header, though the header has been prefected by handler7. The handler4 needs to seek the inputstream with the block starting offset for obtaining the header, while the inputstream has been over read by 33 bytes(the header size). So a new connection to datanode should be recreated, the elder one will be closed. When the datanode writes to a closed channel, a socket exception will be raised. When the same case happens frequently, the datanode will be suffered from logging the message described as it is. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383565#comment-15383565 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 6:32 AM: -- Changing from threadlocal to synchronization, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also an inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is much better than threadlocal when acts as a sequential read . How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. was (Author: dengzh): Changing from threadlocal to synchronization, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also an inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal when acts as a sequential read . How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383565#comment-15383565 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 6:24 AM: -- Changing from threadlocal to synchronization, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also an inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal when acts as a sequential read . How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. was (Author: dengzh): Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal when acts as a sequential read . How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383514#comment-15383514 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 6:22 AM: -- Thanks [~stack]. From the logging, it implies that different threads share the same DFSInputStream instance, say 'defaultRpcServer.handler=7'(handler7) and 'defaultRpcServer.handler=4'(handler4), for example. The original will prefect the next block header and cache the header into thread. When defaultRpcServer.handler=4 comes, it first checks that the cached header offset is equal to the the block starting offset, unfortunately these two numbers are unequal(-1 != offset). The handler4 knows nothing about the block header, though the header has been prefected by handler7. The handler4 needs to seek the inputstream with the block starting offset for obtaining the header, while the inputstream has been over read by 33 bytes(the header size). So a new connection to datanode should be recreated, the elder one will be closed. When the datanode writes to a closed channel, a socket exception will be raised. When the same case happens frequently, the datanode will be suffered from logging the message described as it is. was (Author: dengzh): Thanks [~stack]. From the logging, it implies that different threads share the same DFSInputStream instance, say 'defaultRpcServer.handler=7'(handler7) and 'defaultRpcServer.handler=4'(handler4), for example. The original will prefect the next block header and cache the header into thread. When defaultRpcServer.handler=4 comes, it first checks that the cached header offset is equal to the the block starting offset, unfortunately these two numbers are unequal(-1 != offset). The handler4 knows nothing about the block header, though the header has been prefected by handler7. The handler4 needs to seek the inputstream with the block starting offset for obtaining the header, while the inputstream has been over read by 33 bytes(the header size). So a new connection to datanode should be recreated, the elder one will be closed. When the datanode writes to a closed channel, an socket exception will be raised. When the same case happens frequently, the datanode will be suffered from logging the message described as it is. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383565#comment-15383565 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 4:30 AM: -- Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal when acts as a sequential read . How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. was (Author: dengzh): Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal. How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383565#comment-15383565 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 4:22 AM: -- Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal. How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. was (Author: dengzh): Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal. How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383565#comment-15383565 ] Zhihua Deng commented on HBASE-16212: - Changing from threadlocal to a common field, yes there will be a potential synchronization bottleneck, but it better than io operation. So the question here is that how often the connection will be recreated for seeking + reading? The original threadlocal is declared as non static private field here, it means that the created fsreaderimpl instance will be reused later on, also a inputstream is initiated when fsreaderimpl created. Taken the case described in the attached log, The synchronization way is more better than threadlocal. How about concurrent case? the worst case: Thread1.readBlockInternal -> Thread2.readBlockInternal -> Thread3.readBlockInternal -> Thread1.readBlockInternal -> In this case, the synchronization way is equal to threadlocal when taken how many connections will be created into consideration. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383516#comment-15383516 ] Zhihua Deng edited comment on HBASE-16212 at 7/19/16 3:11 AM: -- Test it on my cluster, a hmaster with two regionservers based on hbase-1.1.2, it works. Further test should carry on the master brunch was (Author: dengzh): Test it on my cluster, a hmaster with two regionservers based on hbase-1.1.2, it works. Further test should carry on the master brunch > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383517#comment-15383517 ] Zhihua Deng commented on HBASE-16212: - Test it on my cluster, a hmaster with two regionservers based on hbase-1.1.2, it works. Further test should carry on the master brunch > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383516#comment-15383516 ] Zhihua Deng commented on HBASE-16212: - Test it on my cluster, a hmaster with two regionservers based on hbase-1.1.2, it works. Further test should carry on the master brunch > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: Test it on my cluster, a hmaster with two regionservers based on hbase-1.1.2, it works. Further test should carry on the master brunch) > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15383514#comment-15383514 ] Zhihua Deng commented on HBASE-16212: - Thanks [~stack]. From the logging, it implies that different threads share the same DFSInputStream instance, say 'defaultRpcServer.handler=7'(handler7) and 'defaultRpcServer.handler=4'(handler4), for example. The original will prefect the next block header and cache the header into thread. When defaultRpcServer.handler=4 comes, it first checks that the cached header offset is equal to the the block starting offset, unfortunately these two numbers are unequal(-1 != offset). The handler4 knows nothing about the block header, though the header has been prefected by handler7. The handler4 needs to seek the inputstream with the block starting offset for obtaining the header, while the inputstream has been over read by 33 bytes(the header size). So a new connection to datanode should be recreated, the elder one will be closed. When the datanode writes to a closed channel, an socket exception will be raised. When the same case happens frequently, the datanode will be suffered from logging the message described as it is. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15381648#comment-15381648 ] Zhihua Deng commented on HBASE-16212: - Similar to the case of HBASE-10676. [~lhofhansl], [~zhaojianbo], could you help review this patch, thanks. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15379100#comment-15379100 ] Zhihua Deng commented on HBASE-16212: - Remove the wrong unit test, The TestHFileBlock#testConcurrentReading test the case i want to. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Attachment: HBASE-16212.v2.patch > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, HBASE-16212.v2.patch, > regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Description: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 ... As the pos of this input stream is larger than targetPos(the pos trying to seek), A new connection to the datanode will be created, the older one will be closed as a consequence. When the wrong seeking ops are large, the datanode's block scanner info message is spamming logs, as well as many connections to the same datanode will be created. hadoop version: 2.7.1 was: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 ... As the pos of this input stream is larger than targetPos(the pos trying to seek), A new connection to the datanode will be created, the older one will be closed as a consequence. When the wrong seeking ops are large, the datanode's block scanner info message is spamming logs, as well as many connections to the same datanode will be created. > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. > hadoop version: 2.7.1 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many connections to datanode are created when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Summary: Many connections to datanode are created when doing a large scan (was: Many Connections are created by wrong seeking pos when doing a large scan ) > Many connections to datanode are created when doing a large scan > - > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos when doing a large scan
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Summary: Many Connections are created by wrong seeking pos when doing a large scan (was: Many Connections are created by wrong seeking pos on InputStream) > Many Connections are created by wrong seeking pos when doing a large scan > -- > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15378986#comment-15378986
]
Zhihua Deng edited comment on HBASE-16212 at 7/15/16 8:08 AM:
--
I add log details to DFSInputStream#seek(long targetPos):
{code:borderStyle=solid}
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
{code}
The attached file named 'regionserver-dfsinputstream.log' shows the process.
Also in one of datanodes throws an exceptions of client's sudden close:
java.net.SocketException: Original Exception : java.io.IOException: Connection
reset by peer
at sun.nio.ch.FileChannelImpl.transferTo0(Native Method)
at
sun.nio.ch.FileChannelImpl.transferToDirectlyInternal(FileChannelImpl.java:427)
at
sun.nio.ch.FileChannelImpl.transferToDirectly(FileChannelImpl.java:492)
at sun.nio.ch.FileChannelImpl.transferTo(FileChannelImpl.java:607)
at
org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:223)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendPacket(BlockSender.java:579)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.doSendBlock(BlockSender.java:759)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:706)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:551)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opReadBlock(Receiver.java:116)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:71)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:251)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Connection reset by peer
... 13 more
was (Author: dengzh):
I add log details to DFSInputStream#seek(long targetPos):
{code:borderStyle=solid}
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
{code}
The attached file 'regionserver-dfsinputstream.log' shows the process.
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Improvement
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
> Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log
>
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a consequence. When the wrong seeking ops are large, the
> datanode's block scanner info message is spamming logs, as well as many
> connections to the same datanode will be created.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15378986#comment-15378986
]
Zhihua Deng edited comment on HBASE-16212 at 7/15/16 8:09 AM:
--
I add log details to DFSInputStream#seek(long targetPos):
{code:borderStyle=solid}
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
{code}
The attached file named 'regionserver-dfsinputstream.log' shows the process.
Also in one of datanodes throw an exception of such a sudden close by the
client side:
java.net.SocketException: Original Exception : java.io.IOException: Connection
reset by peer
at sun.nio.ch.FileChannelImpl.transferTo0(Native Method)
at
sun.nio.ch.FileChannelImpl.transferToDirectlyInternal(FileChannelImpl.java:427)
at
sun.nio.ch.FileChannelImpl.transferToDirectly(FileChannelImpl.java:492)
at sun.nio.ch.FileChannelImpl.transferTo(FileChannelImpl.java:607)
at
org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:223)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendPacket(BlockSender.java:579)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.doSendBlock(BlockSender.java:759)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:706)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:551)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opReadBlock(Receiver.java:116)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:71)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:251)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Connection reset by peer
... 13 more
was (Author: dengzh):
I add log details to DFSInputStream#seek(long targetPos):
{code:borderStyle=solid}
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
{code}
The attached file named 'regionserver-dfsinputstream.log' shows the process.
Also in one of datanodes throws an exceptions of client's sudden close:
java.net.SocketException: Original Exception : java.io.IOException: Connection
reset by peer
at sun.nio.ch.FileChannelImpl.transferTo0(Native Method)
at
sun.nio.ch.FileChannelImpl.transferToDirectlyInternal(FileChannelImpl.java:427)
at
sun.nio.ch.FileChannelImpl.transferToDirectly(FileChannelImpl.java:492)
at sun.nio.ch.FileChannelImpl.transferTo(FileChannelImpl.java:607)
at
org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:223)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendPacket(BlockSender.java:579)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.doSendBlock(BlockSender.java:759)
at
org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:706)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:551)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opReadBlock(Receiver.java:116)
at
org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:71)
at
org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:251)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Connection reset by peer
... 13 more
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Improvement
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
> Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log
>
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a
[jira] [Comment Edited] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15378986#comment-15378986
]
Zhihua Deng edited comment on HBASE-16212 at 7/15/16 8:03 AM:
--
I add log details to DFSInputStream#seek(long targetPos):
{code:borderStyle=solid}
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
{code}
The attached file 'regionserver-dfsinputstream.log' shows the process.
was (Author: dengzh):
I add log details to DFSInputStream#seek(long targetPos):
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
The attached file 'regionserver-dfsinputstream.log' shows the process.
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Improvement
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
> Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log
>
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a consequence. When the wrong seeking ops are large, the
> datanode's block scanner info message is spamming logs, as well as many
> connections to the same datanode will be created.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15378986#comment-15378986
]
Zhihua Deng commented on HBASE-16212:
-
I add log details to DFSInputStream#seek(long targetPos):
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
The attached file 'regionserver-dfsinputstream.log' shows the process.
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Improvement
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
> Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log
>
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a consequence. When the wrong seeking ops are large, the
> datanode's block scanner info message is spamming logs, as well as many
> connections to the same datanode will be created.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Attachment: regionserver-dfsinputstream.log > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch, regionserver-dfsinputstream.log > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Attachment: HBASE-16212.patch > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > Attachments: HBASE-16212.patch > > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Status: Open (was: Patch Available) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Status: Patch Available (was: Open) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Priority: Major (was: Trivial) Issue Type: Improvement (was: Test) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Improvement >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: This jira should be closed as the problem this jira describes is ok.) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Test >Affects Versions: 1.1.2 >Reporter: Zhihua Deng >Priority: Trivial > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372772#comment-15372772 ] Zhihua Deng commented on HBASE-16212: - This jira should be closed as the problem this jira describes is ok. > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Test >Affects Versions: 1.1.2 >Reporter: Zhihua Deng >Priority: Trivial > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Issue Type: Test (was: Bug) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Test >Affects Versions: 1.1.2 >Reporter: Zhihua Deng >Priority: Trivial > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Priority: Trivial (was: Major) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng >Priority: Trivial > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 ) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: When the datanode writes to the closed connection, an exception will occur: 2016-06-30 11:21:34,320 TRACE org.apache.hadoop.hdfs.server.datanode.DataNode: DatanodeRegistration(10.130.1.29:50010, datanodeUuid=f3d795cc-2b3b-43b9-90c3-e4157c031d2c, infoPort=50075, infoSecurePort=0, ipcPort=50020, storageInfo=lv=-56;cid=CID-a99b693d-6f26-48fe-ad37-9f8162f70b22;nsid=920937379;c=0):Ignoring exception while serving BP-360285305-10.130.1.11-1444619256876:blk_1105510536_31776579 to /10.130.1.21:39933 java.net.SocketException: Original Exception : java.io.IOException: Connection reset by peer at sun.nio.ch.FileChannelImpl.transferTo0(Native Method) at sun.nio.ch.FileChannelImpl.transferToDirectlyInternal(FileChannelImpl.java:427) at sun.nio.ch.FileChannelImpl.transferToDirectly(FileChannelImpl.java:492) at sun.nio.ch.FileChannelImpl.transferTo(FileChannelImpl.java:607) at org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:223) at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendPacket(BlockSender.java:579) at org.apache.hadoop.hdfs.server.datanode.BlockSender.doSendBlock(BlockSender.java:759) at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:706) at org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:551) at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opReadBlock(Receiver.java:116) at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:71) at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:251) at java.lang.Thread.run(Thread.java:745) Caused by: java.io.IOException: Connection reset by peer ... 13 more By analyzing the regionserver's log, pos - targetPos = 33, which is equal to the length of block header, seen from HFileBlock.java.) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Comment: was deleted (was: The stack trace looks like this: at org.apache.hadoop.hdfs.DFSInputStream.seek(DFSInputStream.java:1509) at org.apache.hadoop.fs.FSDataInputStream.seek(FSDataInputStream.java:62) at org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1357) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockDataInternal(HFileBlock.java:1591) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockData(HFileBlock.java:1470) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:437) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$AbstractScannerV2.readNextDataBlock(HFileReaderV2.java:708) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.isNextBlock(HFileReaderV2.java:833) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.positionForNextBlock(HFileReaderV2.java:828) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2._next(HFileReaderV2.java:845) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.next(HFileReaderV2.java:865) at org.apache.hadoop.hbase.regionserver.StoreFileScanner.next(StoreFileScanner.java:139) at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:108) at org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:596) at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:147) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.populateResult(HRegion.java:5486) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextInternal(HRegion.java:5637) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextRaw(HRegion.java:5424) at org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2395)) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Issue Comment Deleted] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Zhihua Deng updated HBASE-16212:
Comment: was deleted
(was: Yes, these are logs i added to the DFSInputStream#seek(long targetPos):
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
>From the log, it implies that the client(regionserver) reads behind the
>inputstream with 33 bytes)
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Bug
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a consequence. When the wrong seeking ops are large, the
> datanode's block scanner info message is spamming logs, as well as many
> connections to the same datanode will be created.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372280#comment-15372280 ] Zhihua Deng commented on HBASE-16212: - The stack trace looks like this: at org.apache.hadoop.hdfs.DFSInputStream.seek(DFSInputStream.java:1509) at org.apache.hadoop.fs.FSDataInputStream.seek(FSDataInputStream.java:62) at org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1357) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockDataInternal(HFileBlock.java:1591) at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderImpl.readBlockData(HFileBlock.java:1470) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:437) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$AbstractScannerV2.readNextDataBlock(HFileReaderV2.java:708) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.isNextBlock(HFileReaderV2.java:833) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.positionForNextBlock(HFileReaderV2.java:828) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2._next(HFileReaderV2.java:845) at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.next(HFileReaderV2.java:865) at org.apache.hadoop.hbase.regionserver.StoreFileScanner.next(StoreFileScanner.java:139) at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:108) at org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:596) at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:147) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.populateResult(HRegion.java:5486) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextInternal(HRegion.java:5637) at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextRaw(HRegion.java:5424) at org.apache.hadoop.hbase.regionserver.RSRpcServices.scan(RSRpcServices.java:2395) > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[
https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372219#comment-15372219
]
Zhihua Deng commented on HBASE-16212:
-
Yes, these are logs i added to the DFSInputStream#seek(long targetPos):
if(pos > targetPos) {
DFSClient.LOG.info(dfsClient.getClientName() + " seek " +
getCurrentDatanode() + " for " + getCurrentBlock() +
". pos: " + pos + ", targetPos: " + targetPos);
}
>From the log, it implies that the client(regionserver) reads behind the
>inputstream with 33 bytes
> Many Connections are created by wrong seeking pos on InputStream
>
>
> Key: HBASE-16212
> URL: https://issues.apache.org/jira/browse/HBASE-16212
> Project: HBase
> Issue Type: Bug
>Affects Versions: 1.1.2
>Reporter: Zhihua Deng
>
> As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode
> is suffering from logging the same repeatedly. Adding log to DFSInputStream,
> it outputs as follows:
> 2016-07-10 21:31:42,147 INFO
> [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient:
> DFSClient_NONMAPREDUCE_1984924661_1 seek
> DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK]
> for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos:
> 111506876, targetPos: 111506843
> ...
> As the pos of this input stream is larger than targetPos(the pos trying to
> seek), A new connection to the datanode will be created, the older one will
> be closed as a consequence. When the wrong seeking ops are large, the
> datanode's block scanner info message is spamming logs, as well as many
> connections to the same datanode will be created.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
[jira] [Comment Edited] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372133#comment-15372133 ] Zhihua Deng edited comment on HBASE-16212 at 7/12/16 3:44 AM: -- Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 was (Author: dengzh): Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for
[jira] [Comment Edited] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372133#comment-15372133 ] Zhihua Deng edited comment on HBASE-16212 at 7/12/16 3:44 AM: -- Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 was (Author: dengzh): Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372133#comment-15372133 ] Zhihua Deng commented on HBASE-16212: - Some related logs from region server: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Commented] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15372130#comment-15372130 ] Zhihua Deng commented on HBASE-16212: - When the datanode writes to the closed connection, an exception will occur: 2016-06-30 11:21:34,320 TRACE org.apache.hadoop.hdfs.server.datanode.DataNode: DatanodeRegistration(10.130.1.29:50010, datanodeUuid=f3d795cc-2b3b-43b9-90c3-e4157c031d2c, infoPort=50075, infoSecurePort=0, ipcPort=50020, storageInfo=lv=-56;cid=CID-a99b693d-6f26-48fe-ad37-9f8162f70b22;nsid=920937379;c=0):Ignoring exception while serving BP-360285305-10.130.1.11-1444619256876:blk_1105510536_31776579 to /10.130.1.21:39933 java.net.SocketException: Original Exception : java.io.IOException: Connection reset by peer at sun.nio.ch.FileChannelImpl.transferTo0(Native Method) at sun.nio.ch.FileChannelImpl.transferToDirectlyInternal(FileChannelImpl.java:427) at sun.nio.ch.FileChannelImpl.transferToDirectly(FileChannelImpl.java:492) at sun.nio.ch.FileChannelImpl.transferTo(FileChannelImpl.java:607) at org.apache.hadoop.net.SocketOutputStream.transferToFully(SocketOutputStream.java:223) at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendPacket(BlockSender.java:579) at org.apache.hadoop.hdfs.server.datanode.BlockSender.doSendBlock(BlockSender.java:759) at org.apache.hadoop.hdfs.server.datanode.BlockSender.sendBlock(BlockSender.java:706) at org.apache.hadoop.hdfs.server.datanode.DataXceiver.readBlock(DataXceiver.java:551) at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opReadBlock(Receiver.java:116) at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:71) at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:251) at java.lang.Thread.run(Thread.java:745) Caused by: java.io.IOException: Connection reset by peer ... 13 more By analyzing the regionserver's log, pos - targetPos = 33, which is equal to the length of block header, seen from HFileBlock.java. > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng > > As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode > is suffering from logging the same repeatedly. Adding log to DFSInputStream, > it outputs as follows: > 2016-07-10 21:31:42,147 INFO > [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: > DFSClient_NONMAPREDUCE_1984924661_1 seek > DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] > for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: > 111506876, targetPos: 111506843 > ... > As the pos of this input stream is larger than targetPos(the pos trying to > seek), A new connection to the datanode will be created, the older one will > be closed as a consequence. When the wrong seeking ops are large, the > datanode's block scanner info message is spamming logs, as well as many > connections to the same datanode will be created. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Description: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 ... As the pos of this input stream is larger than targetPos(the pos trying to seek), A new connection to the datanode will be created, the older one will be closed as a consequence. When the wrong seeking ops are large, the datanode's block scanner info message is spamming logs, as well as many connections to the same datanode will be created. was: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 > Many Connections are created by wrong seeking pos on InputStream > > > Key: HBASE-16212 > URL: https://issues.apache.org/jira/browse/HBASE-16212 > Project: HBase > Issue Type: Bug >Affects Versions: 1.1.2 >Reporter: Zhihua Deng >
[jira] [Updated] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
[ https://issues.apache.org/jira/browse/HBASE-16212?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Zhihua Deng updated HBASE-16212: Description: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 was: As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO
[jira] [Created] (HBASE-16212) Many Connections are created by wrong seeking pos on InputStream
Zhihua Deng created HBASE-16212: --- Summary: Many Connections are created by wrong seeking pos on InputStream Key: HBASE-16212 URL: https://issues.apache.org/jira/browse/HBASE-16212 Project: HBase Issue Type: Bug Affects Versions: 1.1.2 Reporter: Zhihua Deng As described in https://issues.apache.org/jira/browse/HDFS-8659, the datanode is suffering from logging the same repeatedly. Adding log to DFSInputStream, it outputs as follows: 2016-07-10 21:31:42,147 INFO [B.defaultRpcServer.handler=22,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 111506876, targetPos: 111506843 2016-07-10 21:31:42,715 INFO [B.defaultRpcServer.handler=25,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 113544644, targetPos: 113544611 2016-07-10 21:31:43,341 INFO [B.defaultRpcServer.handler=27,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 115547269, targetPos: 115547236 2016-07-10 21:31:43,950 INFO [B.defaultRpcServer.handler=16,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 117532235, targetPos: 117532202 2016-07-10 21:31:43,988 INFO [B.defaultRpcServer.handler=7,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 119567867, targetPos: 119567834 2016-07-10 21:31:45,228 INFO [B.defaultRpcServer.handler=19,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 121787264, targetPos: 121787231 2016-07-10 21:31:45,254 INFO [B.defaultRpcServer.handler=0,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 123910032, targetPos: 12390 2016-07-10 21:31:46,402 INFO [B.defaultRpcServer.handler=26,queue=2,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 125905163, targetPos: 125905130 2016-07-10 21:31:47,027 INFO [B.defaultRpcServer.handler=24,queue=0,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 128028947, targetPos: 128028914 2016-07-10 21:31:47,649 INFO [B.defaultRpcServer.handler=10,queue=1,port=16020] hdfs.DFSClient: DFSClient_NONMAPREDUCE_1984924661_1 seek DatanodeInfoWithStorage[10.130.1.29:50010,DS-086bc494-d862-470c-86e8-9cb7929985c6,DISK] for BP-360285305-10.130.1.11-1444619256876:blk_1109360829_35627143. pos: 130057763, targetPos: 130057730 -- This message was sent by Atlassian JIRA (v6.3.4#6332)
