[jira] [Commented] (HDFS-9126) namenode crash in fsimage download/transfer
[
https://issues.apache.org/jira/browse/HDFS-9126?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16083601#comment-16083601
]
linhaiqiang commented on HDFS-9126:
---
We have already encounter simliar issue. As logs shown, an unexpected 45 sec
timeout occured when active namenode's corresponding healthMonitor was checking
namenode's health(health check request emited at 2017-07-06 17:22:12). The
timeout makes healthMonitor believes active namenode had failed, and thus
closed zk client to quit leader election. However, we did not find any
exception in namenode's log and gc log. A more wired thing is that namenode's
ends logging at 2017-07-06 17:20:37.
After analysing the source code, the scenario is shown below:
1. when activce namenode' corresponding healthMonitor is checking NN's health,
a 45 secends timeout makes state switched to SERVICE_NOT_RESPONDING.
2. Active NN quits leader election. zkClinet close connection and, thus,
temporary lock znode on zk is deleted.
3. standby NN gain the leadership from zk in order to switch itself to new
active NN.
4. To prevent 'Split-Brain', before switching to active state, standby NN sends
rpc request to switch current active NN' state to standby.
5. If this rpc request fails, standby NN tries to kill target NN jvm via ssh.
This is the exactly same to our case.
6. After killing target NN successfully, standby NN switchs itself to activce.
Though we have understood the scenario, what happend in previous active NN is
still unknown. Sadly, Jstack trace can be found no longer since jvm is killed
by standby nn. Does anyone understand or have similar prolem? Thanks for
sharing in advance.
namenode log
2017-07-06 17:20:25,944 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap
updated: 192.168.74.160:50010 is added to
blk_8181385931_7145837309{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-8b015249-3dfc-46d6-b575-a5217dd3e40e:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-a88850be-de4f-4cf8-b6ec-10c8116c4226:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-09006ca0-3bd0-41a2-b4b9-90a28682031b:NORMAL|RBW]]}
size 0
2017-07-06 17:20:25,945 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap
updated: 192.168.8.230:50010 is added to
blk_8181385931_7145837309{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-8b015249-3dfc-46d6-b575-a5217dd3e40e:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-a88850be-de4f-4cf8-b6ec-10c8116c4226:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-09006ca0-3bd0-41a2-b4b9-90a28682031b:NORMAL|RBW]]}
size 0
2017-07-06 17:20:25,945 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap
updated: 192.168.74.79:50010 is added to
blk_8181385931_7145837309{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-8b015249-3dfc-46d6-b575-a5217dd3e40e:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-a88850be-de4f-4cf8-b6ec-10c8116c4226:NORMAL|RBW],
ReplicaUnderConstruction[[DISK]DS-09006ca0-3bd0-41a2-b4b9-90a28682031b:NORMAL|RBW]]}
size 0
2017-07-06 17:20:25,945 INFO org.apache.hadoop.hdfs.StateChange: DIR*
completeFile:
/tmp/hive-mobdss/hive_2017-07-06_17-19-52_775_5225473556650420863-1/_task_tmp.-ext-10003/_tmp.00_0
is closed by DFSClient_attempt_1482378778761_39818303_m_00_0_1289941958_1
2017-07-06 17:20:25,946 INFO org.apache.hadoop.hdfs.StateChange: DIR*
completeFile:
/hbase/data/ns_spider/p_site_product/2a79796e1be609fc26ecf1ab58f5aac9/.tmp/733c7b7008594135ae6fcb540f0ca4d5
is closed by
DFSClient_hb_rs_slave557-prd3.hadoop.com,60020,1498730232536_-2089669913_35
2017-07-06 17:20:26,667 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync:
/tmp/hadoop-yarn/staging/mobdss/.staging/job_1482378778761_39818325/job_1482378778761_39818325_1.jhist
for DFSClient_NONMAPREDUCE_-907911548_1
2017-07-06 17:20:30,826 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync:
/tmp/hadoop-yarn/staging/yyadmin/.staging/job_1482378778761_39818328/job_1482378778761_39818328_1.jhist
for DFSClient_NONMAPREDUCE_-1343712942_1
2017-07-06 17:20:32,051 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync:
/tmp/hadoop-yarn/staging/yyadmin/.staging/job_1482378778761_39818327/job_1482378778761_39818327_1.jhist
for DFSClient_NONMAPREDUCE_-904958265_1
2017-07-06 17:20:33,722 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* fsync:
/tmp/hadoop-yarn/staging/yyadmin/.staging/job_1482378778761_39818341/job_1482378778761_39818341_1.jhist
for DFSClient_NONMAPREDUCE_1250585342_1
2017-07-06 17:20:37,402 INFO
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor:
Rescanning after 3 milliseconds
zkfc log
2017-07-06 17:22:12,264 WARN org.apache.hadoop.ha.HealthMonitor:
Transport-level exception trying to monitor health of Na
meNode at hostname1/hostname1:8020: Call From hostname1/hostname1 to
namenode1-pr
[jira] [Issue Comment Deleted] (HDFS-9126) namenode crash in fsimage download/transfer
[ https://issues.apache.org/jira/browse/HDFS-9126?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] linhaiqiang updated HDFS-9126: -- Comment: was deleted (was: Similar questions, 2017-07-06 17:22:12 active namenode health monitor 45 seconds timeout, active namenode exit election, ZK connection closed However, there is no new log generation for the namenode log from 2017-07-06 17:20:37 and no exception log and The GC log looks normal Through the source code analysis, the abnormal process is as follows 1. The healthMonitor at the active node causes a 45 second timeout during the detection of the NN state to cause access to the SERVICE_NOT_RESPONDING state 2. The active node exits the election, the zkClient closes to the ZOOKEEPER connection, and the temporary lock znode on the ZK automatically deletes 3. The standby node gets the temporary lock ZK on the znode and starts switching itself to active To prevent the presence of 2 active brain clefts at the same time, the active is first converted to standby by the RPC request 4. If the RPC request is blocked, then connect the past kill to the NameNode process by way of SSH 5. After success, you change yourself into a active node But why 45 seconds timeout, because the process was kill, can not find the time jstack stack information, there is no way to find) > namenode crash in fsimage download/transfer > --- > > Key: HDFS-9126 > URL: https://issues.apache.org/jira/browse/HDFS-9126 > Project: Hadoop HDFS > Issue Type: Bug > Components: namenode >Affects Versions: 2.6.0 > Environment: OS:Centos 6.5(final) > Apache Hadoop:2.6.0 > namenode ha base 5 journalnodes >Reporter: zengyongping >Priority: Critical > > In our product Hadoop cluster,when active namenode begin download/transfer > fsimage from standby namenode.some times zkfc monitor health of NameNode > socket timeout,zkfs judge active namenode status SERVICE_NOT_RESPONDING > ,happen hadoop namenode ha failover,fence old active namenode. > zkfc logs: > 2015-09-24 11:44:44,739 WARN org.apache.hadoop.ha.HealthMonitor: > Transport-level exception trying to monitor health of NameNode at > hostname1/192.168.10.11:8020: Call From hostname1/192.168.10.11 to > hostname1:8020 failed on socket timeout exception: > java.net.SocketTimeoutException: 45000 millis timeout while waiting for > channel to be ready for read. ch : java.nio.channels.SocketChannel[connected > local=/192.168.10.11:22614 remote=hostname1/192.168.10.11:8020]; For more > details see: http://wiki.apache.org/hadoop/SocketTimeout > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.HealthMonitor: Entering > state SERVICE_NOT_RESPONDING > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ZKFailoverController: Local > service NameNode at hostname1/192.168.10.11:8020 entered state: > SERVICE_NOT_RESPONDING > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ZKFailoverController: > Quitting master election for NameNode at hostname1/192.168.10.11:8020 and > marking that fencing is necessary > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ActiveStandbyElector: > Yielding from election > 2015-09-24 11:44:44,761 INFO org.apache.zookeeper.ZooKeeper: Session: > 0x54d81348fe503e3 closed > 2015-09-24 11:44:44,761 WARN org.apache.hadoop.ha.ActiveStandbyElector: > Ignoring stale result from old client with sessionId 0x54d81348fe503e3 > 2015-09-24 11:44:44,764 INFO org.apache.zookeeper.ClientCnxn: EventThread > shut down > namenode logs: > 2015-09-24 11:43:34,074 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from > 192.168.10.12 > 2015-09-24 11:43:34,074 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs > 2015-09-24 11:43:34,075 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment > 2317430129 > 2015-09-24 11:43:34,253 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: > 272988 Total time for transactions(ms): 5502 Number of transactions batched > in Syncs: 146274 Number of syncs: 32375 SyncTimes(ms): 274465 319599 > 2015-09-24 11:43:46,005 INFO > org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: > Rescanning after 3 milliseconds > 2015-09-24 11:44:21,054 WARN > org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: > PendingReplicationMonitor timed out blk_1185804191_112164210 > 2015-09-24 11:44:36,076 INFO > org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits > file > /software/data/hadoop-data/hdfs/namenode/current/edits_inprogress_02317430129 > -> > /software/data/hadoop-data/hdfs/namenode/current/edits_02317430129-02317703116 > 2015-09-24 11:44:36,077 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at >
[jira] [Commented] (HDFS-9126) namenode crash in fsimage download/transfer
[ https://issues.apache.org/jira/browse/HDFS-9126?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16083354#comment-16083354 ] linhaiqiang commented on HDFS-9126: --- Similar questions, 2017-07-06 17:22:12 active namenode health monitor 45 seconds timeout, active namenode exit election, ZK connection closed However, there is no new log generation for the namenode log from 2017-07-06 17:20:37 and no exception log and The GC log looks normal Through the source code analysis, the abnormal process is as follows 1. The healthMonitor at the active node causes a 45 second timeout during the detection of the NN state to cause access to the SERVICE_NOT_RESPONDING state 2. The active node exits the election, the zkClient closes to the ZOOKEEPER connection, and the temporary lock znode on the ZK automatically deletes 3. The standby node gets the temporary lock ZK on the znode and starts switching itself to active To prevent the presence of 2 active brain clefts at the same time, the active is first converted to standby by the RPC request 4. If the RPC request is blocked, then connect the past kill to the NameNode process by way of SSH 5. After success, you change yourself into a active node But why 45 seconds timeout, because the process was kill, can not find the time jstack stack information, there is no way to find > namenode crash in fsimage download/transfer > --- > > Key: HDFS-9126 > URL: https://issues.apache.org/jira/browse/HDFS-9126 > Project: Hadoop HDFS > Issue Type: Bug > Components: namenode >Affects Versions: 2.6.0 > Environment: OS:Centos 6.5(final) > Apache Hadoop:2.6.0 > namenode ha base 5 journalnodes >Reporter: zengyongping >Priority: Critical > > In our product Hadoop cluster,when active namenode begin download/transfer > fsimage from standby namenode.some times zkfc monitor health of NameNode > socket timeout,zkfs judge active namenode status SERVICE_NOT_RESPONDING > ,happen hadoop namenode ha failover,fence old active namenode. > zkfc logs: > 2015-09-24 11:44:44,739 WARN org.apache.hadoop.ha.HealthMonitor: > Transport-level exception trying to monitor health of NameNode at > hostname1/192.168.10.11:8020: Call From hostname1/192.168.10.11 to > hostname1:8020 failed on socket timeout exception: > java.net.SocketTimeoutException: 45000 millis timeout while waiting for > channel to be ready for read. ch : java.nio.channels.SocketChannel[connected > local=/192.168.10.11:22614 remote=hostname1/192.168.10.11:8020]; For more > details see: http://wiki.apache.org/hadoop/SocketTimeout > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.HealthMonitor: Entering > state SERVICE_NOT_RESPONDING > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ZKFailoverController: Local > service NameNode at hostname1/192.168.10.11:8020 entered state: > SERVICE_NOT_RESPONDING > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ZKFailoverController: > Quitting master election for NameNode at hostname1/192.168.10.11:8020 and > marking that fencing is necessary > 2015-09-24 11:44:44,740 INFO org.apache.hadoop.ha.ActiveStandbyElector: > Yielding from election > 2015-09-24 11:44:44,761 INFO org.apache.zookeeper.ZooKeeper: Session: > 0x54d81348fe503e3 closed > 2015-09-24 11:44:44,761 WARN org.apache.hadoop.ha.ActiveStandbyElector: > Ignoring stale result from old client with sessionId 0x54d81348fe503e3 > 2015-09-24 11:44:44,764 INFO org.apache.zookeeper.ClientCnxn: EventThread > shut down > namenode logs: > 2015-09-24 11:43:34,074 INFO > org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from > 192.168.10.12 > 2015-09-24 11:43:34,074 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs > 2015-09-24 11:43:34,075 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment > 2317430129 > 2015-09-24 11:43:34,253 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: > 272988 Total time for transactions(ms): 5502 Number of transactions batched > in Syncs: 146274 Number of syncs: 32375 SyncTimes(ms): 274465 319599 > 2015-09-24 11:43:46,005 INFO > org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor: > Rescanning after 3 milliseconds > 2015-09-24 11:44:21,054 WARN > org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: > PendingReplicationMonitor timed out blk_1185804191_112164210 > 2015-09-24 11:44:36,076 INFO > org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits > file > /software/data/hadoop-data/hdfs/namenode/current/edits_inprogress_02317430129 > -> > /software/data/hadoop-data/hdfs/namenode/current/edits_02317430129-02317703116 > 2015-09-24 11:44:36,077 INFO > org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at
[jira] [Updated] (HDFS-4949) Centralized cache management in HDFS
[ https://issues.apache.org/jira/browse/HDFS-4949?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] linhaiqiang updated HDFS-4949: -- Fix Version/s: (was: 2.3.0) > Centralized cache management in HDFS > > > Key: HDFS-4949 > URL: https://issues.apache.org/jira/browse/HDFS-4949 > Project: Hadoop HDFS > Issue Type: New Feature > Components: datanode, namenode >Affects Versions: 3.0.0, 2.3.0 >Reporter: Andrew Wang >Assignee: Andrew Wang > Attachments: HDFS-4949-consolidated.patch, > caching-design-doc-2013-07-02.pdf, caching-design-doc-2013-08-09.pdf, > caching-design-doc-2013-10-24.pdf, caching-testplan.pdf, > hdfs-4949-branch-2.patch > > > HDFS currently has no support for managing or exposing in-memory caches at > datanodes. This makes it harder for higher level application frameworks like > Hive, Pig, and Impala to effectively use cluster memory, because they cannot > explicitly cache important datasets or place their tasks for memory locality. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
