AnsweredAssumed Answered

Mappers getting stuck in sortAndWrite

Question asked by jerdavis on Nov 22, 2013
Hello,
I've run in to an issue using 3.0.2. And I'm not sure if it is a bug or if I'm just doing things wrong...
I start a map task and it seems to stall out  (in the first round of Mappers) in sortAndWrite.
Cpu's are at 25% per mapper, and there is negligible disk IO.
The MapR GUI says Network IO is constant 100MB/sec In and Out, and I see it is all on the loopback.
This problem seems related to the number of reduce tasks. It occurs if I have 70K, it does not if I have 700. The data size and cardinality is large enough that at 70K it is still several minutes per reduce task, and I was hoping to make use of reduce.input.buffer to keep the data in memory.
I believe I've set io.sort.mb such that all the map data should also be sorted in memory (which I can verify by # of Spilled Tuples when I use a smaller number of reduce tasks)..

Is this expected behavior? is 70K just too big of a number?


     # CPU % CPU used
    CPU: 24 23
    In (per sec) Out (per sec)
    Network I/O:  127.7MB  127.1MB
    Count (per sec) In (per sec) Out (per sec)
    RPC I/O: 909  124.8MB  227.9KB
    Reads (per sec) Writes (per sec)
    Disk I/O:  8KB  4.2MB
    # Operations: 1 31

    "pool-3-thread-1" prio=10 tid=0x00007f33a86e1000 nid=0x1df3 runnable [0x00007f3388a15000]
       java.lang.Thread.State: RUNNABLE
     at com.mapr.fs.jni.MapRClient.createFid(Native Method)
     at com.mapr.fs.MapRClientImpl.createFid(MapRClientImpl.java:203)
     at com.mapr.fs.MapRFileSystem.createFid(MapRFileSystem.java:2253)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer$1.call(MapTask.java:1766)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer$1.call(MapTask.java:1755)
     at java.util.concurrent.FutureTask.run(FutureTask.java:262)
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
     at java.lang.Thread.run(Thread.java:724)
    
    "Thread-8" daemon prio=10 tid=0x00007f33a86e0800 nid=0x1df2 runnable [0x00007f3388b16000]
       java.lang.Thread.State: RUNNABLE
     at com.mapr.fs.jni.MapRClient.writeRPC(Native Method)
     at com.mapr.fs.Inode.flushPages(Inode.java:367)
     at com.mapr.fs.Inode.syncInternal(Inode.java:489)
     at com.mapr.fs.Inode.sync(Inode.java:502)
     at com.mapr.fs.Inode.closeWrite(Inode.java:512)
     - locked <0x00000000e3d65750> (a com.mapr.fs.Inode)
     at com.mapr.fs.Inode.close(Inode.java:961)
     at com.mapr.fs.MapRFsOutStream.close(MapRFsOutStream.java:215)
     - locked <0x00000000e3d65728> (a com.mapr.fs.MapRFsOutStream)
     at com.mapr.fs.MapRFsDataOutputStream.close(MapRFsDataOutputStream.java:57)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer$CloserThread.run(MapTask.java:1684)
    
    "SpillThread" daemon prio=10 tid=0x00007f33a8748800 nid=0x1dc3 waiting on condition [0x00007f3389b7f000]
       java.lang.Thread.State: WAITING (parking)
     at sun.misc.Unsafe.park(Native Method)
     - parking to wait for  <0x00000000d377edc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
     at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
     at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer$SpillThread.run(MapTask.java:1476)
    
    "communication thread" daemon prio=10 tid=0x00007f33a8b03000 nid=0x1db6 in Object.wait() [0x00007f3389cb9000]
       java.lang.Thread.State: TIMED_WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x00000000d37db648> (a java.util.concurrent.atomic.AtomicBoolean)
     at org.apache.hadoop.mapred.Task$TaskReporter.run(Task.java:664)
     - locked <0x00000000d37db648> (a java.util.concurrent.atomic.AtomicBoolean)
     at java.lang.Thread.run(Thread.java:724)
    
    "Thread for syncLogs" daemon prio=10 tid=0x00007f33a87d0800 nid=0x1d93 waiting on condition [0x00007f338d078000]
       java.lang.Thread.State: TIMED_WAITING (sleeping)
     at java.lang.Thread.sleep(Native Method)
     at org.apache.hadoop.mapred.Child$3.run(Child.java:155)
    
    "sendParams-0" daemon prio=10 tid=0x00007f33a87ce800 nid=0x1d91 waiting on condition [0x00007f338d179000]
       java.lang.Thread.State: TIMED_WAITING (parking)
     at sun.misc.Unsafe.park(Native Method)
     - parking to wait for  <0x00000000d37db730> (a java.util.concurrent.SynchronousQueue$TransferStack)
     at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
     at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
     at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
     at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)
     at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
     at java.lang.Thread.run(Thread.java:724)
    
    "IPC Client (47) connection to /127.0.0.1:49197 from job_201311180909_5495" daemon prio=10 tid=0x00007f33a8660800 nid=0x1d8d in Object.wait() [0x00007f338d27a000]
       java.lang.Thread.State: TIMED_WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x00000000d37db7d8> (a org.apache.hadoop.ipc.Client$Connection)
     at org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:681)
     - locked <0x00000000d37db7d8> (a org.apache.hadoop.ipc.Client$Connection)
     at org.apache.hadoop.ipc.Client$Connection.run(Client.java:724)
    
    "Service Thread" daemon prio=10 tid=0x00007f33a80b8000 nid=0x1cd0 runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C2 CompilerThread1" daemon prio=10 tid=0x00007f33a80b5800 nid=0x1ccf waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C2 CompilerThread0" daemon prio=10 tid=0x00007f33a80b3800 nid=0x1cce waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "Signal Dispatcher" daemon prio=10 tid=0x00007f33a80a9800 nid=0x1ccd runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "Finalizer" daemon prio=10 tid=0x00007f33a8091800 nid=0x1ca2 in Object.wait() [0x00007f3394d7c000]
       java.lang.Thread.State: WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x00000000d3724540> (a java.lang.ref.ReferenceQueue$Lock)
     at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
     - locked <0x00000000d3724540> (a java.lang.ref.ReferenceQueue$Lock)
     at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
     at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)
    
    "Reference Handler" daemon prio=10 tid=0x00007f33a8088000 nid=0x1c9c in Object.wait() [0x00007f3394e7d000]
       java.lang.Thread.State: WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x00000000d3724218> (a java.lang.ref.Reference$Lock)
     at java.lang.Object.wait(Object.java:503)
     at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
     - locked <0x00000000d3724218> (a java.lang.ref.Reference$Lock)
    
    "main" prio=10 tid=0x00007f33a800d000 nid=0x1c60 waiting on condition [0x00007f33ad0dc000]
       java.lang.Thread.State: WAITING (parking)
     at sun.misc.Unsafe.park(Native Method)
     - parking to wait for  <0x00000000d4bf27e0> (a java.util.concurrent.FutureTask)
     at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
     at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:425)
     at java.util.concurrent.FutureTask.get(FutureTask.java:187)
     at java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:243)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer.sortAndWrite(MapTask.java:1820)
     at org.apache.hadoop.mapred.MapTask$MapOutputBuffer.flush(MapTask.java:1421)
     - locked <0x00000000d377eea8> (a org.apache.hadoop.mapred.MapTask$MapOutputBuffer)
     at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:419)
     at org.apache.hadoop.mapred.MapTask.run(MapTask.java:349)
     at org.apache.hadoop.mapred.Child$4.run(Child.java:270)
     at java.security.AccessController.doPrivileged(Native Method)
     at javax.security.auth.Subject.doAs(Subject.java:415)
     at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1127)
     at org.apache.hadoop.mapred.Child.main(Child.java:264)

    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               1.58   32.08    3.70    1.07    0.00   61.56
    
    Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
    sda              20.39        82.96      2545.24  414786208 12726196624
    sdb              39.95      2421.03      3257.10 12105137696 16285515680
    sdc              39.77      2422.29      3252.85 12111448952 16264243184
    sde              13.26      1633.59      2036.60 8167933800 10183015712
    sdd              39.97      2438.34      3257.57 12191709256 16287831664
    sdf              13.22      1626.95      2035.83 8134771176 10179130208
    sdg              13.23      1625.35      2039.01 8126757352 10195067344
    sdh              15.07      1881.03      2214.16 9405149656 11070803424
    sdj              15.03      1871.64      2217.06 9358210152 11085290864
    sdi              15.03      1879.71      2216.21 9398565032 11081035168
    sdm              17.16      2105.25      2632.19 10526265800 13160962176
    sdn               0.00         0.01         0.00      67400          0
    sdl              15.23      1827.41      2293.15 9137052856 11465722704
    sdk              15.26      1825.85      2298.95 9129230008 11494741008
    dm-0            298.39        12.08      2380.47   60408930 11902334592
    dm-1             29.45        70.81       164.75  354061952  823747312
    dm-2              0.01         0.06         0.02     283130     114552
        
I also noticed this in the Mfs log, but things seem generally ok (and not spewing)

    2013-11-22 09:16:40,2698 INFO  containerresync.cc:3900 x.x.0.0:0 Skipping delete resync snapshot 4272325628, wa 21a88e000 as container not found
    2013-11-22 09:16:42,1314 ERROR  ctable.cc:172 x.x.0.0:0 container 11414 is not available on this server yet
    2013-11-22 09:16:42,1315 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (11414) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1316 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (11414) failed on replica with error (111)
    2013-11-22 09:16:42,1316 ERROR  ctable.cc:172 x.x.0.0:0 container 6924 is not available on this server yet
    2013-11-22 09:16:42,1316 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (6924) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1316 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (6924) failed on replica with error (111)
    2013-11-22 09:16:42,1316 ERROR  ctable.cc:172 x.x.0.0:0 container 4919 is not available on this server yet
    2013-11-22 09:16:42,1317 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (4919) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1317 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (4919) failed on replica with error (111)
    2013-11-22 09:16:42,1317 ERROR  ctable.cc:172 x.x.0.0:0 container 10027 is not available on this server yet
    2013-11-22 09:16:42,1318 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (10027) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1318 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (10027) failed on replica with error (111)
    2013-11-22 09:16:42,1318 ERROR  ctable.cc:172 x.x.0.0:0 container 5532 is not available on this server yet
    2013-11-22 09:16:42,1318 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (5532) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1318 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (5532) failed on replica with error (111)
    2013-11-22 09:16:42,1319 ERROR  ctable.cc:172 x.x.0.0:0 container 5760 is not available on this server yet
    2013-11-22 09:16:42,1319 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (5760) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1319 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (5760) failed on replica with error (111)
    2013-11-22 09:16:42,1319 ERROR  ctable.cc:172 x.x.0.0:0 container 4098 is not available on this server yet
    2013-11-22 09:16:42,1319 ERROR  replicateops.cc:2271 x.x.0.0:0 Failed to GetContainer (19) for replicated op (0) on container (4098) of type (37) from 10.100.0.115:5660. Rejecting the op.
    2013-11-22 09:16:42,1319 INFO  replicateops.cc:2891 x.x.0.0:0 Op (37) from 10.100.0.115:5660 with version (0) on container (4098) failed on replica with error (111)
    2013-11-22 09:18:37,4173 INFO  servercommand.cc:667 x.x.0.0:0 Container Delete command from cldb for cid 2630.
    2013-11-22 09:18:37,4173 INFO  servercommand.cc:667 x.x.0.0:0 Container Delete command from cldb for cid 13385.
    2013-11-22 09:18:37,4603 INFO  servercommand.cc:667 x.x.0.0:4861 Container Delete command from cldb for cid 4981.


Outcomes