I'm trying to figure out why, when I use a single input file that is relatively small (< 3 MB, ~95K records), my Reducer hangs at 33% and the attempt never completes, with the output below. It looks like there's a problem when it tries to write to the log file, for some reason it gets Interrupted which is not handled, and the Thread then terminates without ever catching that Exception and so the Reducer Task sits there until the JobTracker kills it and starts up another one. Which inevitably hits the same one.
When I take that same data, and split it up into multiple files (5, 10, whichever, just >1), then it runs fine, no issues. Very strange, anyone have any ideas? --Aaron stderr logs log4j:ERROR Failed to flush writer, java.io.InterruptedIOException at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:58) at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:316) at org.apache.log4j.WriterAppender.append(WriterAppender.java:160) at org.apache.hadoop.mapred.TaskLogAppender.append(TaskLogAppender.java:58) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66) at org.apache.log4j.Category.callAppenders(Category.java:206) at org.apache.log4j.Category.forcedLog(Category.java:391) at org.apache.log4j.Category.log(Category.java:856) at org.apache.commons.logging.impl.Log4JLogger.info(Log4JLogger.java:199) at org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler.freeHost(ShuffleScheduler.java:345) at org.apache.hadoop.mapreduce.task.reduce.Fetcher.run(Fetcher.java:152) syslog logs 2011-03-15 17:02:32,258 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=SHUFFLE, sessionId= 2011-03-15 17:02:32,265 WARN org.apache.hadoop.conf.Configuration: user.name is deprecated. Instead, use mapreduce.job.user.name 2011-03-15 17:02:32,360 WARN org.apache.hadoop.conf.Configuration: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id 2011-03-15 17:02:32,413 INFO org.apache.hadoop.mapreduce.task.reduce.MergeManager: MergerManager: memoryLimit=130514944, maxSingleShuffleLimit=32628736, mergeThreshold=86139864, ioSortFactor=10, memToMemMergeOutputsThreshold=10 2011-03-15 17:02:32,416 INFO org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_201103141158_0104_r_000000_0 Thread started: EventFetcher for fetching Map Completion Events 2011-03-15 17:02:32,423 INFO org.apache.hadoop.mapreduce.task.reduce.EventFetcher: attempt_201103141158_0104_r_000000_0: Got 1 new map-outputs 2011-03-15 17:02:32,423 INFO org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: Assiging 10.10.11.50:50060 with 1 to fetcher#5 2011-03-15 17:02:32,423 INFO org.apache.hadoop.mapreduce.task.reduce.ShuffleScheduler: assigned 1 of 1 to 10.10.11.50:50060 to fetcher#5 2011-03-15 17:02:32,730 INFO org.apache.hadoop.mapreduce.task.reduce.Fetcher: for url=50060/mapOutput?job=job_201103141158_0104&reduce=0&map=attempt_201103141158_0104_m_000000_0 sent hash and receievd reply 2011-03-15 17:02:32,735 INFO org.apache.hadoop.mapreduce.task.reduce.Fetcher: fetcher#5 about to shuffle output of map attempt_201103141158_0104_m_000000_0 decomp: 2050216 len: 2050220 to MEMORY 2011-03-15 17:02:32,790 INFO org.apache.hadoop.mapreduce.task.reduce.Fetcher: Read 2050216 bytes from map-output for attempt_201103141158_0104_m_000000_0 2011-03-15 17:02:32,790 INFO org.apache.hadoop.mapreduce.task.reduce.MergeManager: closeInMemoryFile -> map-output of size: 2050216, inMemoryMapOutputs.size() -> 1