title: Determine cause of Hadoop error in code, as standard logs inconclusive: file splits, container memory, or block size
body: <p>For a while now I've been going through the <code>log4j</code> logs trying to determine why my Hadoop job is crashing. </p>
  
  <p>Essentially what the job attempts to do is issue a command on the underlying machine, and collect the output of that command- at the moment point all of these steps takes place in a map job (<em>later I'll try to reduce over the sum of those individual outputs</em>). </p>
  
  <p>The behaviour I'm experiencing is that- for a certain number of outputs generated to the <code>BufferedReader</code>, for sake of conversation- <code>28</code> of them, everything works fine and the job finishes almost immediately, <strong>however</strong> when I increase that number to <code>29</code>, the map job hangs at <code>67%</code> completion- attempts it three times- always stopping at <code>67%</code> and finally terminates itself for lack of progress. </p>
  
  <p>From the NameNode where the job is issued we can see the following output: </p>
  
  <pre><code>17/10/09 15:19:29 WARN mapreduce.JobResourceUploader: Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner to remedy this.
  17/10/09 15:19:29 INFO input.FileInputFormat: Total input files to process : 1
  17/10/09 15:19:30 INFO mapreduce.JobSubmitter: number of splits:1
  17/10/09 15:19:30 INFO mapreduce.JobSubmitter: Submitting tokens for job: job_1507562353923_0001
  17/10/09 15:19:30 INFO impl.YarnClientImpl: Submitted application application_1507562353923_0001
  17/10/09 15:19:30 INFO mapreduce.Job: The url to track the job: http://master:8088/proxy/application_1507562353923_0001/
  17/10/09 15:19:30 INFO mapreduce.Job: Running job: job_1507562353923_0001
  17/10/09 15:19:36 INFO mapreduce.Job: Job job_1507562353923_0001 running in uber mode : false
  17/10/09 15:19:36 INFO mapreduce.Job:  map 0% reduce 0%
  17/10/09 15:19:53 INFO mapreduce.Job:  map 67% reduce 0%
  17/10/09 15:30:05 INFO mapreduce.Job: Task Id : attempt_1507562353923_0001_m_000000_0, Status : FAILED
  AttemptID:attempt_1507562353923_0001_m_000000_0 Timed out after 600 secs
  Sent signal OUTPUT_THREAD_DUMP (SIGQUIT) to pid 6230 as user ubuntu for container container_1507562353923_0001_01_000002, result=success
  Container killed by the ApplicationMaster.
  Container killed on request. Exit code is 143
  Container exited with a non-zero exit code 143
  
  17/10/09 15:30:06 INFO mapreduce.Job:  map 0% reduce 0%
  17/10/09 15:30:26 INFO mapreduce.Job:  map 67% reduce 0%
  17/10/09 15:40:36 INFO mapreduce.Job: Task Id : attempt_1507562353923_0001_m_000000_1, Status : FAILED
  AttemptID:attempt_1507562353923_0001_m_000000_1 Timed out after 600 secs
  17/10/09 15:40:37 INFO mapreduce.Job:  map 0% reduce 0%
  17/10/09 15:40:52 INFO mapreduce.Job:  map 67% reduce 0%
  17/10/09 15:51:05 INFO mapreduce.Job: Task Id : attempt_1507562353923_0001_m_000000_2, Status : FAILED
  AttemptID:attempt_1507562353923_0001_m_000000_2 Timed out after 600 secs
  17/10/09 15:51:06 INFO mapreduce.Job:  map 0% reduce 0%
  17/10/09 15:51:24 INFO mapreduce.Job:  map 67% reduce 0%
  17/10/09 16:01:37 INFO mapreduce.Job:  map 100% reduce 100%
  17/10/09 16:01:37 INFO mapreduce.Job: Job job_1507562353923_0001 failed with state FAILED due to: Task failed task_1507562353923_0001_m_000000
  Job failed as tasks failed. failedMaps:1 failedReduces:0
  
  17/10/09 16:01:37 INFO mapreduce.Job: Counters: 13
      Job Counters 
          Failed map tasks=4
          Killed reduce tasks=1
          Launched map tasks=4
          Other local map tasks=3
          Data-local map tasks=1
          Total time spent by all maps in occupied slots (ms)=5025782
          Total time spent by all reduces in occupied slots (ms)=0
          Total time spent by all map tasks (ms)=2512891
          Total time spent by all reduce tasks (ms)=0
          Total vcore-milliseconds taken by all map tasks=2512891
          Total vcore-milliseconds taken by all reduce tasks=0
          Total megabyte-milliseconds taken by all map tasks=10292801536
          Total megabyte-milliseconds taken by all reduce tasks=0
  </code></pre>
  
  <p>To determine the root cause of this problem I've spent many hours meticulously pouring over the <code>log4j</code> output logs, but they don't turn up anything conclusive- for instance- they look almost identical for sucessful jobs and unsuccessful jobs, with the minor caveat that unsucessful jobs, abruptly terminate like so: </p>
  
  <p><a href="https://i.stack.imgur.com/I6c1y.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/I6c1y.png" alt="enter image description here"></a></p>
  
  <p>The most interesting part seems to be here (from one of the previous attempts(Hadoop always makes 3 tries at completing the job)): </p>
  
  <pre><code>2017-10-09 15:40:35,821 WARN [main] OpcodeCount$TokenizerMapper: Code: opAdd, Time: 214
  2017-10-09 15:40:35,821 WARN [main] OpcodeCount$TokenizerMapper: Code: opAdd, Time: 450
  2017-10-09 15:40:35,821 WARN [main] OpcodeCount$TokenizerMapper: Code: opAdd, Time: 217
  2017-10-09 15:40:35,821 WARN [main] OpcodeCount$TokenizerMapper: Code: opStop, Time: 165
  2017-10-09 15:40:35,851 INFO [main] org.apache.hadoop.mapred.MapTask: Starting flush of map output
  2017-10-09 15:40:35,851 INFO [main] org.apache.hadoop.mapred.MapTask: Spilling map output
  2017-10-09 15:40:35,851 INFO [main] org.apache.hadoop.mapred.MapTask: bufstart = 0; bufend = 1977; bufvoid = 104857600
  2017-10-09 15:40:35,851 INFO [main] org.apache.hadoop.mapred.MapTask: kvstart = 26214396(104857584); kvend = 26214396(104857584); length = 1/6553600
  (&amp;container_1507562353923_0001_01_000005???stderr0stdout105912017-10-09 16:01:35
  Full thread dump OpenJDK 64-Bit Server VM (25.131-b11 mixed mode):
  </code></pre>
  
  <p>The word "<em>Full thread</em>" lead me to believe that my <code>MapOutputBuffer</code> was filling up, as described in <a href="http://ercoppa.github.io/HadoopInternals/AnatomyMapReduceJob.html" rel="nofollow noreferrer">this article</a>, I tried the recommended to solution of increasing the size in my configuration files, i.e. increasing <code>mapreduce.task.io.sort.mb</code>, to <code>1000</code>, and <code>mapreduce.map.sort.spill.percent</code> to <code>0.99</code>, but it had no positive effect. </p>
  
  <p>The next thing I tried was to change the program from outputting the debug/sanity check output in the form of a <code>Log</code> from log4j, and instead have it write that to a file as <a href="https://stackoverflow.com/questions/16000840/write-a-file-in-hdfs-with-java">decribed here</a>, but that also didn't work.</p>
  
  <hr>
  
  <p>At the moment my ideas of what could be wrong with this program are as follows: </p>
  
  <p>1) <code>MapOutputBuffer</code> is filling up causing the program to stall out</p>
  
  <p>Something I should mention is that- it's important for one file to execute as an atomic map task- if the command from the file gets broken up into smaller component pieces, the operation that it issues to the underlying OS won't make sense- therefore: </p>
  
  <p>2) The input file is broken up inside of HDFS and not being read in as one sequential unit- in the correct order</p>
  
  <p>3) That the command is being broken up between containers and that part of the command is being issued in one container, while another container takes care of the other part- thereby causing the issue I just specified above.</p>
  
  <hr>
  
  <p>So then as the logs have been inconclusive my next goal is to change my code in some way such that I can isolate, test for, and eliminate each one of these possibilities --> any ideas on how I can do that in an efficient way- or any and all comments, insights, remarks about anything else I've written here will be much appreciated. </p>
  
  <p>Here's how the map job is written at the moment: </p>
  
  <pre><code>  public static class TokenizerMapper extends Mapper&lt;Object, Text, Text, IntWritable&gt;{
  
      private final static IntWritable one = new IntWritable(1);
      private Text word = new Text();
  
      // declare logger
      private final Logger LOG = org.apache.log4j.Logger.getLogger(this.getClass());
  
      public void map(Object key, Text value, Context context) throws IOException, InterruptedException {
  
        // output data struct
        List&lt;Map.Entry&lt;String,Integer&gt;&gt; pairList = new ArrayList&lt;&gt;();
  
        StringTokenizer itr = new StringTokenizer(value.toString());
        while (itr.hasMoreTokens()) {
            try {
                // command execution
                Runtime rt = Runtime.getRuntime();
                String evmDir = "/home/ubuntu/go/src/github.com/ethereum/go-ethereum/build/bin/evm";
                String command = evmDir + " --debug --code " + value.toString() + " run";
                Process proc = Runtime.getRuntime().exec(command);
  
                LOG.warn(command);
  
                BufferedReader stdInput = new BufferedReader(new InputStreamReader(proc.getInputStream()));
                BufferedReader stdError = new BufferedReader(new InputStreamReader(proc.getErrorStream()));
  
                // define and initialise representation to hold 'evm' command output
                ArrayList&lt;String&gt; consoleOutput = new ArrayList&lt;String&gt;();
                ArrayList&lt;String&gt; debugOutput   = new ArrayList&lt;String&gt;();
  
                String s = null;
                while ((s = stdInput.readLine()) != null) {
                    consoleOutput.add(s);
                }
                while ((s = stdError.readLine()) != null) {
                    debugOutput.add(s);
                }
  
                for (String p : consoleOutput) {
                    Pattern pattern = Pattern.compile("([A-Za-z]+)([ \t]+)(\\d+)");
                    Matcher matcher = pattern.matcher(p);
                    while (matcher.find()) {
                        String opcodeName = matcher.group(1);
                        Integer executionStepTime = Integer.valueOf(matcher.group(3));
                        // add component pieces of line to output data structure
                        pairList.add(new AbstractMap.SimpleEntry&lt;&gt;(opcodeName, executionStepTime));
                    }
                }
  
            } catch (IOException e) {
                //LOG.warn(e);
                LOG.warn("Exception Encountered! " + e);
            }
  
            // log output for debugging
            for (Map.Entry&lt;String, Integer&gt; entry : pairList) {
                String opcodeRep = entry.getKey().toString();
                Integer stepTime = entry.getValue();
                LOG.warn("Code: " + opcodeRep + ", Time: " + stepTime);
            }
  
            word.set(itr.nextToken());
            context.write(word, one);
        }
      }
    }
  </code></pre>
  
  <p>Maybe this addtional information from the logs looks like it could be pertinent to correctly diagnosing this issue: </p>
  
  <pre><code>"VM Thread" os_prio=0 tid=0x00007f0a1007a000 nid=0x7328 runnable 
  
  "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f0a10026000 nid=0x7326 runnable 
  
  "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f0a10027800 nid=0x7327 runnable 
  
  "VM Periodic Task Thread" os_prio=0 tid=0x00007f0a100bc800 nid=0x732f waiting on condition 
  
  JNI global references: 277
  
  Heap
   PSYoungGen      total 100352K, used 7502K [0x0000000780000000, 0x0000000788a00000, 0x00000007c0000000)
    eden space 94720K, 2% used [0x0000000780000000,0x0000000780216d78,0x0000000785c80000)
    from space 5632K, 95% used [0x0000000788480000,0x00000007889bcbc8,0x0000000788a00000)
    to   space 8192K, 0% used [0x0000000787a00000,0x0000000787a00000,0x0000000788200000)
   ParOldGen       total 143360K, used 113628K [0x0000000700000000, 0x0000000708c00000, 0x0000000780000000)
    object space 143360K, 79% used [0x0000000700000000,0x0000000706ef71d0,0x0000000708c00000)
   Metaspace       used 25981K, capacity 26224K, committed 26496K, reserved 1073152K
    class space    used 3019K, capacity 3083K, committed 3200K, reserved 1048576K
  </code></pre>