You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-issues@hadoop.apache.org by "ASF GitHub Bot (Jira)" <ji...@apache.org> on 2023/06/07 08:59:00 UTC

[jira] [Commented] (HDFS-16583) DatanodeAdminDefaultMonitor can get stuck in an infinite loop

    [ https://issues.apache.org/jira/browse/HDFS-16583?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17730011#comment-17730011 ] 

ASF GitHub Bot commented on HDFS-16583:
---------------------------------------

Kidd53685368 commented on PR #4332:
URL: https://github.com/apache/hadoop/pull/4332#issuecomment-1580240331

   It seems the problem won't keeping holding the writeLock because of the exceededNumBlocksPerCheck()?




> DatanodeAdminDefaultMonitor can get stuck in an infinite loop
> -------------------------------------------------------------
>
>                 Key: HDFS-16583
>                 URL: https://issues.apache.org/jira/browse/HDFS-16583
>             Project: Hadoop HDFS
>          Issue Type: Bug
>            Reporter: Stephen O'Donnell
>            Assignee: Stephen O'Donnell
>            Priority: Major
>              Labels: pull-request-available
>             Fix For: 3.4.0, 3.2.4, 3.3.5
>
>          Time Spent: 2h
>  Remaining Estimate: 0h
>
> We encountered a case where the decommission monitor in the namenode got stuck for about 6 hours. The logs give:
> {code}
> 2022-05-15 01:09:25,490 INFO org.apache.hadoop.hdfs.server.blockmanagement.HeartbeatManager: Stopping maintenance of dead node 10.185.3.132:50010
> 2022-05-15 01:10:20,918 INFO org.apache.hadoop.http.HttpServer2: Process Thread Dump: jsp requested
> <Thread dump>
> 2022-05-15 01:19:06,810 WARN org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: PendingReconstructionMonitor timed out blk_4501753665_3428271426
> 2022-05-15 01:19:06,810 WARN org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: PendingReconstructionMonitor timed out blk_4501753659_3428271420
> 2022-05-15 01:19:06,810 WARN org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: PendingReconstructionMonitor timed out blk_4501753662_3428271423
> 2022-05-15 01:19:06,810 WARN org.apache.hadoop.hdfs.server.blockmanagement.BlockManager: PendingReconstructionMonitor timed out blk_4501753663_3428271424
> 2022-05-15 06:00:57,281 INFO org.apache.hadoop.hdfs.server.blockmanagement.HeartbeatManager: Stopping maintenance of dead node 10.185.3.34:50010
> 2022-05-15 06:00:58,105 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: FSNamesystem write lock held for 17492614 ms via
> java.lang.Thread.getStackTrace(Thread.java:1559)
> org.apache.hadoop.util.StringUtils.getStackTrace(StringUtils.java:1032)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystemLock.writeUnlock(FSNamesystemLock.java:263)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystemLock.writeUnlock(FSNamesystemLock.java:220)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.writeUnlock(FSNamesystem.java:1601)
> org.apache.hadoop.hdfs.server.blockmanagement.DatanodeAdminManager$Monitor.run(DatanodeAdminManager.java:496)
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> java.lang.Thread.run(Thread.java:748)
> 	Number of suppressed write-lock reports: 0
> 	Longest write-lock held interval: 17492614
> {code}
> We only have the one thread dump triggered by the FC:
> {code}
> Thread 80 (DatanodeAdminMonitor-0):
>   State: RUNNABLE
>   Blocked count: 16
>   Waited count: 453693
>   Stack:
>     org.apache.hadoop.hdfs.server.blockmanagement.DatanodeAdminManager$Monitor.check(DatanodeAdminManager.java:538)
>     org.apache.hadoop.hdfs.server.blockmanagement.DatanodeAdminManager$Monitor.run(DatanodeAdminManager.java:494)
>     java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>     java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>     java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>     java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>     java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
>     java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
>     java.lang.Thread.run(Thread.java:748)
> {code}
> This was the line of code:
> {code}
>     private void check() {
>       final Iterator<Map.Entry<DatanodeDescriptor, AbstractList<BlockInfo>>>
>           it = new CyclicIteration<>(outOfServiceNodeBlocks,
>               iterkey).iterator();
>       final LinkedList<DatanodeDescriptor> toRemove = new LinkedList<>();
>       while (it.hasNext() && !exceededNumBlocksPerCheck() && namesystem
>           .isRunning()) {
>         numNodesChecked++;
>         final Map.Entry<DatanodeDescriptor, AbstractList<BlockInfo>>
>             entry = it.next();
>         final DatanodeDescriptor dn = entry.getKey();
>         AbstractList<BlockInfo> blocks = entry.getValue();
>         boolean fullScan = false;
>         if (dn.isMaintenance() && dn.maintenanceExpired()) {
>           // If maintenance expires, stop tracking it.
>           stopMaintenance(dn);
>           toRemove.add(dn);
>           continue;
>         }
>         if (dn.isInMaintenance()) {
>           // The dn is IN_MAINTENANCE and the maintenance hasn't expired yet.
>           continue;  //// >>> This line
>         }
> {code}
> With only one sample, we cannot figure out for sure if it is somehow stuck in an infinite loop, but I suspect it is.
> The problem is two fold:
> 1) When we call stopMaintenance(dn), which we must have done as it logged the "Stopping maintenance of dead node", the code looks like:
> {code}
>        if (dn.isMaintenance() && dn.maintenanceExpired()) {
>           // If maintenance expires, stop tracking it.
>           stopMaintenance(dn);
>           toRemove.add(dn);
>           continue;
>         }
> {code}
> Notice we add the DN to the toRemove list - this is to avoid concurrent modifications on the outOfServiceNodeBlocks map. However inside stopMaintenance we see:
> {code}
>       pendingNodes.remove(node);
>       outOfServiceNodeBlocks.remove(node);
> {code}      
> This should cause a concurrentModification exception, which I think will leave the decommission monitor broken until the NN is restarted normally (again I am not sure).
> 2) In some cases a ConcurrentModificationException is not thrown. This is because the iterator is a CyclicIterator. If the DN removed from maintenance is the one after the iterator start key, and its the second last element in the navigatable map, I believe the CyclicIterator will go into an infinite loop. No concurrent modification exception will get thrown, as the TreeMap iterator has no next(), so it creates a new TreeMap iterator, and then the "stop key" for the cyclic iterator is never found in the map as its now gone, and it just cycles forever. I think that is what happened here.
> This test in TestCyclicIteration proves the infinite loop is possible:
> {code}
>   @Test
>   public void testInfiniteLoop() {
>     final NavigableMap<Integer, Integer> map = new TreeMap<Integer, Integer>();
>     map.put(0, 0);
>     map.put(2, 2);
>     map.put(4, 4);
>     map.put(6, 6);
>     System.out.println("map=" + map);
>     // Create iterator to start at 2, which means the first element returned
>     // should be 4.
>     // Inside the treemap iterator, next will already be set to 6
>     // after 4 is returned.
>     final Iterator<Map.Entry<Integer, Integer>>
>         it =  new CyclicIteration<>(map, 2).iterator();
>     int i = 0;
>     while(it.hasNext()) {
>       Map.Entry<Integer, Integer> e = it.next();
>       if (i == 0) {
>         map.remove(4);
>       }
>       System.out.println("Iteration #" + i++);
>     }
>   }
> {code}
> The root cause of the decommission monitor problem is the concurrentModification of the outOfServiceNodeBlocks - so we should avoid that.



--
This message was sent by Atlassian Jira
(v8.20.10#820010)

---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org