Uploaded image for project: 'Hadoop Map/Reduce'
  1. Hadoop Map/Reduce
  2. MAPREDUCE-5423

Rare deadlock situation when reducers try to fetch map output

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Duplicate
    • 2.0.2-alpha
    • None
    • mrv2
    • None

    Description

      During our cluster deployment, we found there is a very rare deadlock situation when reducers try to fetch map output. We had 5 fetchers and log snippet illustrates this problem is below (all fetchers went into a wait state after they can't acquire more RAM beyond the memoryLimit and no fetcher is releasing memory):

      2013-07-18 04:32:28,135 INFO [main] org.apache.hadoop.mapreduce.task.reduce.MergeManager: MergerManager: memoryLimit=1503238528, maxSingleShuffleLimit=375809632, mergeThreshold=992137472, ioSortFactor=10, memToMemMergeOutputsThreshold=10
      2013-07-18 04:32:28,138 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0 Thread started: EventFetcher for fetching Map Completion Events
      2013-07-18 04:32:28,146 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:28,146 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 1 to fetcher#1
      2013-07-18 04:32:28,146 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 101-09-04.sc1.verticloud.com:8080 to fetcher#1
      2013-07-18 04:32:28,319 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000017_0 sent hash and receievd reply
      2013-07-18 04:32:28,320 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1373902166027_0622_m_000017_0 decomp: 27 len: 31 to MEMORY
      2013-07-18 04:32:28,325 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 27 bytes from map-output for attempt_1373902166027_0622_m_000017_0
      2013-07-18 04:32:28,325 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 27, inMemoryMapOutputs.size() -> 1, commitMemory -> 0, usedMemory ->27
      2013-07-18 04:32:28,325 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#1 in 179s
      2013-07-18 04:32:33,158 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:33,158 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 1 to fetcher#1
      2013-07-18 04:32:33,158 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 101-09-04.sc1.verticloud.com:8080 to fetcher#1
      2013-07-18 04:32:33,161 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000016_0 sent hash and receievd reply
      2013-07-18 04:32:33,200 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1373902166027_0622_m_000016_0 decomp: 55841282 len: 55841286 to MEMORY
      2013-07-18 04:32:33,322 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 55841282 bytes from map-output for attempt_1373902166027_0622_m_000016_0
      2013-07-18 04:32:33,323 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 55841282, inMemoryMapOutputs.size() -> 2, commitMemory -> 27, usedMemory ->55841309
      2013-07-18 04:32:39,594 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 118022137 bytes from map-output for attempt_1373902166027_0622_m_000015_0
      2013-07-18 04:32:39,594 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 118022137, inMemoryMapOutputs.size() -> 3, commitMemory -> 55841309, usedMemory ->173863446
      2013-07-18 04:32:39,594 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#1 in 413s
      2013-07-18 04:32:42,188 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:42,188 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 1 to fetcher#1
      2013-07-18 04:32:42,188 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 101-09-04.sc1.verticloud.com:8080 to fetcher#1
      2013-07-18 04:32:42,190 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000014_0 sent hash and receievd reply
      2013-07-18 04:32:42,277 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1373902166027_0622_m_000014_0 decomp: 140715962 len: 140715966 to MEMORY
      2013-07-18 04:32:42,493 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 140715962 bytes from map-output for attempt_1373902166027_0622_m_000014_0
      2013-07-18 04:32:42,493 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 140715962, inMemoryMapOutputs.size() -> 4, commitMemory -> 173863446, usedMemory ->314579408
      2013-07-18 04:32:42,494 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#1 in 306s
      2013-07-18 04:32:43,192 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:43,192 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 1 to fetcher#1
      2013-07-18 04:32:43,192 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 101-09-04.sc1.verticloud.com:8080 to fetcher#1
      2013-07-18 04:32:43,195 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000013_0 sent hash and receievd reply
      2013-07-18 04:32:43,280 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1373902166027_0622_m_000013_0 decomp: 141243082 len: 141243086 to MEMORY
      2013-07-18 04:32:43,506 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 141243082 bytes from map-output for attempt_1373902166027_0622_m_000013_0
      2013-07-18 04:32:43,506 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 141243082, inMemoryMapOutputs.size() -> 5, commitMemory -> 314579408, usedMemory ->455822490
      2013-07-18 04:32:43,507 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#1 in 315s
      2013-07-18 04:32:44,195 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:44,195 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 1 to fetcher#1
      2013-07-18 04:32:44,195 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 101-09-04.sc1.verticloud.com:8080 to fetcher#1
      2013-07-18 04:32:44,198 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000011_0 sent hash and receievd reply
      2013-07-18 04:32:44,305 INFO fetcher#1 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#1 about to shuffle output of map attempt_1373902166027_0622_m_000011_0 decomp: 173528412 len: 173528416 to MEMORY
      ...
      2013-07-18 04:32:56,901 INFO fetcher#2 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 282474777 bytes from map-output for attempt_1373902166027_0622_m_000001_0
      2013-07-18 04:32:56,901 INFO fetcher#2 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 282474777, inMemoryMapOutputs.size() -> 5, commitMemory -> 1179552807, usedMemory ->1462027584
      2013-07-18 04:32:56,901 INFO fetcher#2 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#2 in 2682s
      2013-07-18 04:32:56,901 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 4 to fetcher#4
      2013-07-18 04:32:56,902 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 4 of 4 to 101-09-04.sc1.verticloud.com:8080 to fetcher#4
      2013-07-18 04:32:56,904 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000006_0,attempt_1373902166027_0622_m_000002_0,attempt_1373902166027_0622_m_000003_0,attempt_1373902166027_0622_m_000005_0 sent hash and receievd reply
      2013-07-18 04:32:57,336 INFO [EventFetcher for fetching Map Completion Events] org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_1373902166027_0622_r_000001_0: Got 1 new map-outputs
      2013-07-18 04:32:57,414 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#4 about to shuffle output of map attempt_1373902166027_0622_m_000006_0 decomp: 280156692 len: 280156696 to MEMORY
      2013-07-18 04:32:57,867 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 280156692 bytes from map-output for attempt_1373902166027_0622_m_000006_0
      2013-07-18 04:32:57,867 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 280156692, inMemoryMapOutputs.size() -> 6, commitMemory -> 1462027584, usedMemory ->1742184276
      2013-07-18 04:32:57,900 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#4 - MergerManager returned Status.WAIT ...
      2013-07-18 04:32:57,901 INFO fetcher#4 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: 101-09-04.sc1.verticloud.com:8080 freed by fetcher#4 in 999s
      2013-07-18 04:32:57,901 INFO fetcher#3 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 101-09-04.sc1.verticloud.com:8080 with 4 to fetcher#3
      2013-07-18 04:32:57,901 INFO fetcher#3 org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 4 of 4 to 101-09-04.sc1.verticloud.com:8080 to fetcher#3
      2013-07-18 04:32:57,903 INFO fetcher#3 org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=8080/mapOutput?job=job_1373902166027_0622&reduce=1&map=attempt_1373902166027_0622_m_000000_0,attempt_1373902166027_0622_m_000002_0,attempt_1373902166027_0622_m_000005_0,attempt_1373902166027_0622_m_000003_0 sent hash and receievd reply
      2013-07-18 04:32:57,904 INFO fetcher#3 org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#3 - MergerManager returned Status.WAIT ...
      ...

      Attachments

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. MAPREDUCE-4842 Shuffle race can hang reducer

          • Blocker - Blocks development and/or testing work, production could not run
          • Closed

          Activity

            People

              Unassigned Unassigned
              stayhf Chu Tong
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: