title: hadoop: reduce happened between flush map output and finish spill before maps done
body: <p>I'm new to hadoop, and i'm trying the examples wordcount/secondsort in src/examples.</p>
  
  <p>wordcount test environment:</p>
  
  <p>input:</p>
  
  <p>file01.txt</p>
  
  <p>file02.txt</p>
  
  <p>secondsort test environment:</p>
  
  <p>input:</p>
  
  <p>sample01.txt</p>
  
  <p>sample02.txt</p>
  
  <p>Which means both the two test would have 2 paths to process.
  I print some log info trying to understand the process of map/reduce.</p>
  
  <p>See what's between <strong>Starting flush of map output</strong> and <strong>Finished spill 0</strong>:
  the wordcount program has another two reduce task before a final reduce while 
  the secondsort program just do the reduce once and it's done.
  Since these programs are so "small", i dont think the io.sort.mb/io.sort.refactor would affect this.</p>
  
  <p>Can anybody explain this? </p>
  
  <p>Thanks for your patience for my broken Englisth and the long log.</p>
  
  <p>These are the log info (i cut some useless info to make it short):</p>
  
  <pre><code>wordcount log:
  
  [hadoop@localhost ~]$ hadoop jar test.jar com.abc.example.test wordcount output
  13/08/07 18:14:05 INFO mapred.FileInputFormat: Total input paths to process : 2
  13/08/07 18:14:06 INFO mapred.JobClient: Running job: job_local_0001
  13/08/07 18:14:06 INFO util.ProcessTree: setsid exited with exit code 0
  ...
  13/08/07 18:14:06 INFO mapred.MapTask: numReduceTasks: 1
  13/08/07 18:14:06 INFO mapred.MapTask: io.sort.mb = 100
  13/08/07 18:14:06 INFO mapred.MapTask: data buffer = 79691776/99614720
  13/08/07 18:14:06 INFO mapred.MapTask: record buffer = 262144/327680
  Mapper: 0 | Hello Hadoop GoodBye Hadoop
  13/08/07 18:14:06 INFO mapred.MapTask: **Starting flush of map output**
  Reduce: GoodBye
  Reduce: GoodBye | 1
  Reduce: Hadoop
  Reduce: Hadoop | 1
  Reduce: Hadoop | 1
  Reduce: Hello
  Reduce: Hello | 1
  13/08/07 18:14:06 INFO mapred.Task: Task:attempt_local_0001_m_000000_0 is done. And is in the process of commiting
  13/08/07 18:14:06 INFO mapred.LocalJobRunner: hdfs://localhost:8020/user/hadoop/wordcount/file02.txt:0+28
  13/08/07 18:14:06 INFO mapred.Task: Task 'attempt_local_0001_m_000000_0' done.
  13/08/07 18:14:06 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@4d16ffed
  13/08/07 18:14:06 INFO mapred.MapTask: numReduceTasks: 1
  13/08/07 18:14:06 INFO mapred.MapTask: io.sort.mb = 100
  13/08/07 18:14:06 INFO mapred.MapTask: data buffer = 79691776/99614720
  13/08/07 18:14:06 INFO mapred.MapTask: record buffer = 262144/327680
  13/08/07 18:14:06 INFO mapred.MapTask: **Starting flush of map output**
  Reduce: Bye
  Reduce: Bye | 1
  Reduce: Hello
  Reduce: Hello | 1
  Reduce: world
  Reduce: world | 1
  Reduce: world | 1
  13/08/07 18:14:06 INFO mapred.MapTask: **Finished spill 0**
  13/08/07 18:14:06 INFO mapred.Task: Task:attempt_local_0001_m_000001_0 is done. And is in the process of commiting
  13/08/07 18:14:06 INFO mapred.LocalJobRunner: hdfs://localhost:8020/user/hadoop/wordcount/file01.txt:0+22
  13/08/07 18:14:06 INFO mapred.Task: Task 'attempt_local_0001_m_000001_0' done.
  13/08/07 18:14:06 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1f3c0665
  13/08/07 18:14:06 INFO mapred.LocalJobRunner: 
  13/08/07 18:14:06 INFO mapred.Merger: Merging 2 sorted segments
  13/08/07 18:14:06 INFO mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 77 bytes
  13/08/07 18:14:06 INFO mapred.LocalJobRunner: 
  Reduce: Bye
  Reduce: Bye | 1
  Reduce: GoodBye
  Reduce: GoodBye | 1
  Reduce: Hadoop
  Reduce: Hadoop | 2
  Reduce: Hello
  Reduce: Hello | 1
  Reduce: Hello | 1
  Reduce: world
  Reduce: world | 2
  13/08/07 18:14:06 INFO mapred.Task: Task:attempt_local_0001_r_000000_0 is done. And is in the process of commiting
  ...
  13/08/07 18:14:07 INFO mapred.JobClient:     Reduce input groups=5
  13/08/07 18:14:07 INFO mapred.JobClient:     Combine output records=6
  13/08/07 18:14:07 INFO mapred.JobClient:     Physical memory (bytes) snapshot=0
  13/08/07 18:14:07 INFO mapred.JobClient:     Reduce output records=5
  13/08/07 18:14:07 INFO mapred.JobClient:     Virtual memory (bytes) snapshot=0
  13/08/07 18:14:07 INFO mapred.JobClient:     Map output records=8
  
  secondsort log info:
  
  [hadoop@localhost ~]$ hadoop jar example.jar com.abc.example.example secondsort output
  13/08/07 17:00:11 INFO input.FileInputFormat: Total input paths to process : 2
  13/08/07 17:00:11 WARN snappy.LoadSnappy: Snappy native library not loaded
  13/08/07 17:00:12 INFO mapred.JobClient: Running job: job_local_0001
  13/08/07 17:00:12 INFO util.ProcessTree: setsid exited with exit code 0
  13/08/07 17:00:12 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@57d94c7b
  13/08/07 17:00:12 INFO mapred.MapTask: io.sort.mb = 100
  13/08/07 17:00:12 INFO mapred.MapTask: data buffer = 79691776/99614720
  13/08/07 17:00:12 INFO mapred.MapTask: record buffer = 262144/327680
  Map: 0 | 5 49
  Map: 5 | 9 57
  Map: 10 | 19 46
  Map: 16 | 3 21
  Map: 21 | 9 48
  Map: 26 | 7 57
  ... 
  13/08/07 17:00:12 INFO mapred.MapTask: **Starting flush of map output**
  13/08/07 17:00:12 INFO mapred.MapTask: **Finished spill 0**
  13/08/07 17:00:12 INFO mapred.Task: Task:attempt_local_0001_m_000000_0 is done. And is in the process of commiting
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: 
  13/08/07 17:00:12 INFO mapred.Task: Task 'attempt_local_0001_m_000000_0' done.
  13/08/07 17:00:12 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@f3a1ea1
  13/08/07 17:00:12 INFO mapred.MapTask: io.sort.mb = 100
  13/08/07 17:00:12 INFO mapred.MapTask: data buffer = 79691776/99614720
  13/08/07 17:00:12 INFO mapred.MapTask: record buffer = 262144/327680
  Map: 0 | 20 21
  Map: 6 | 50 51
  Map: 12 | 50 52
  Map: 18 | 50 53
  Map: 24 | 50 54
  ...
  13/08/07 17:00:12 INFO mapred.MapTask: **Starting flush of map output**
  13/08/07 17:00:12 INFO mapred.MapTask: **Finished spill 0**
  13/08/07 17:00:12 INFO mapred.Task: Task:attempt_local_0001_m_000001_0 is done. And is in the process of commiting
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: 
  13/08/07 17:00:12 INFO mapred.Task: Task 'attempt_local_0001_m_000001_0' done.
  13/08/07 17:00:12 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@cee4e92
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: 
  13/08/07 17:00:12 INFO mapred.Merger: Merging 2 sorted segments
  13/08/07 17:00:12 INFO mapred.Merger: Down to the last merge-pass, with 2 segments left of total size: 1292 bytes
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: 
  Reduce: 0:35 -----------------
  Reduce: 0:35 | 35
  Reduce: 0:54 -----------------
  ... 
  13/08/07 17:00:12 INFO mapred.Task: Task:attempt_local_0001_r_000000_0 is done. And is in the process of commiting
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: 
  13/08/07 17:00:12 INFO mapred.Task: Task attempt_local_0001_r_000000_0 is allowed to commit now
  13/08/07 17:00:12 INFO output.FileOutputCommitter: Saved output of task 'attempt_local_0001_r_000000_0' to output
  13/08/07 17:00:12 INFO mapred.LocalJobRunner: reduce &gt; reduce
  13/08/07 17:00:12 INFO mapred.Task: Task 'attempt_local_0001_r_000000_0' done.
  13/08/07 17:00:13 INFO mapred.JobClient:  map 100% reduce 100%
  13/08/07 17:00:13 INFO mapred.JobClient: Job complete: job_local_0001
  13/08/07 17:00:13 INFO mapred.JobClient: Counters: 22
  13/08/07 17:00:13 INFO mapred.JobClient:   File Output Format Counters 
  13/08/07 17:00:13 INFO mapred.JobClient:     Bytes Written=4787
  ...
  13/08/07 17:00:13 INFO mapred.JobClient:     SPLIT_RAW_BYTES=236
  13/08/07 17:00:13 INFO mapred.JobClient:     Reduce input records=92
  </code></pre>
  
  <p><strong>PS: The main()s for others to check out.</strong></p>
  
  <p>wordcount:</p>
  
  <pre><code>public static void main(String[] args) throws Exception {
       JobConf conf = new JobConf(test.class);
       conf.setJobName("wordcount");
  
       conf.setOutputKeyClass(Text.class);
       conf.setOutputValueClass(IntWritable.class);
  
       conf.setMapperClass(Map.class);
       conf.setCombinerClass(Reduce.class);
       conf.setReducerClass(Reduce.class);
  
       conf.setInputFormat(TextInputFormat.class);
       conf.setOutputFormat(TextOutputFormat.class);
  
       FileInputFormat.setInputPaths(conf, new Path(args[0]));
       FileOutputFormat.setOutputPath(conf, new Path(args[1]));
  
       JobClient.runJob(conf);
     }
  </code></pre>
  
  <p>secondsort:</p>
  
  <pre><code>public static void main(String[] args) throws IOException, InterruptedException, ClassNotFoundException
      {
          Configuration conf = new Configuration();
          Job job = new Job(conf, "secondarysort");
          job.setJarByClass(example.class);
          job.setMapperClass(Map.class);
          job.setReducerClass(Reduce.class);
          job.setPartitionerClass(FirstPartitioner.class);
          job.setGroupingComparatorClass(GroupingComparator.class);
  
          job.setMapOutputKeyClass(IntPair.class);
          job.setMapOutputValueClass(IntWritable.class);
          job.setOutputKeyClass(Text.class);
          job.setOutputValueClass(IntWritable.class);
  
          job.setInputFormatClass(TextInputFormat.class);
          job.setOutputFormatClass(TextOutputFormat.class);
  
          FileInputFormat.setInputPaths(job, new Path(args[0]));
          FileOutputFormat.setOutputPath(job, new Path(args[1]));
          System.exit(job.waitForCompletion(true) ? 0 : 1);
      }
  </code></pre>