Déterminez la cause de l'erreur Hadoop dans le code, comme les journaux standards non concluants: fractionnements de fichiers, mémoire de conteneur ou taille de bloc

Question

Depuis un moment, je parcours les journaux log4j pour essayer de déterminer pourquoi mon travail Hadoop plante. Essentiellement ce que le travail tente de faire est d'émettre une commande sur la machine sous-jacente, et de recueillir la sortie de cette commande - au moment où toutes ces étapes ont lieu dans un travail de carte (plus tard, je vais essayer de réduire sur la somme de ces sorties individuelles).

Le comportement que je rencontre est that- pour un certain nombre de résultats générés au BufferedReader, pour l'amour de leur 28 conversation: tout fonctionne bien et le travail se termine presque immédiatement, mais quand j'augmente que numéro à 29, le travail de la carte se bloque à 67% achèvement - il tente trois fois - toujours s'arrêter à 67% et se termine finalement par manque de progrès.

De l'NameNode où le travail est publié, nous pouvons voir la sortie suivante:

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 

Pour déterminer la cause de ce problème, je l'ai passé de nombreuses heures à verser méticuleusement sur les journaux de sortie log4j, mais ils ne pas tourner quoi que ce soit pour conclusive- exemple- ils semblent presque identiques pour les emplois et les emplois sucessful sans succès, avec la mise en garde que les emplois mineurs unsucessful, se terminent brusquement comme ceci:

La partie la plus intéressante semble être ici (d'une des tentatives précédentes (Hadoop fait toujours 3 essais à terminer le travail)):

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 
(&container_1507562353923_0001_01_000005???stderr0stdout105912017-10-09 16:01:35 
Full thread dump OpenJDK 64-Bit Server VM (25.131-b11 mixed mode): 

Le mot « fil pleine » me mènent à croire que mon MapOutputBuffer remplissait, comme décrit dans this article, j'ai essayé le recommandé à la solution d'augmenter la taille dans mes fichiers de configuration, soit mapreduce.task.io.sort.mb, à 1000, et mapreduce.map.sort.spill.percent à 0.99, mais il n'a eu aucun effet positif. La prochaine chose que j'ai essayé a été de changer le programme de sortie de la sortie de vérification debug/sanity sous la forme d'un Log de log4j, et à la place l'écrire dans un fichier comme decribed here, mais cela n'a pas fonctionné .

---

Au moment mes idées de ce qui pourrait être mal avec ce programme sont les suivants:

1) MapOutputBuffer est remplissage provoquant un plantage du programme sur

Quelque chose que je dois mentionner que - il est important qu'un fichier s'exécute en tant que tâche de carte atomique - si la commande du fichier est décomposée en composants plus petits, l'opération qu'il envoie au système d'exploitation sous-jacent n'aura aucun sens:

2 L'inpu

3) que la commande est répartie entre les conteneurs et que la partie de la commande est émise dans un conteneur, le fichier t est fragmenté à l'intérieur de HDFS et n'est pas lu en tant qu'unité séquentielle; tandis qu'un autre conteneur prend soin de l'autre partie, provoquant ainsi le problème que je viens de spécifier ci-dessus.

---

Alors que les journaux ont été peu concluantes mon prochain objectif est de changer mon code d'une manière telle que je peux isoler, tester et éliminer chacun de ces possibilités -> des idées sur la façon dont je Je peux le faire d'une manière efficace - ou tous les commentaires, idées, remarques sur tout ce que j'ai écrit ici seront très appréciés.

Voilà comment le travail de la carte est écrit au moment:

public static class TokenizerMapper extends Mapper<Object, Text, Text, IntWritable>{ 

    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<Map.Entry<String,Integer>> pairList = new ArrayList<>(); 

     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<String> consoleOutput = new ArrayList<String>(); 
       ArrayList<String> debugOutput = new ArrayList<String>(); 

       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<>(opcodeName, executionStepTime)); 
        } 
       } 

      } catch (IOException e) { 
       //LOG.warn(e); 
       LOG.warn("Exception Encountered! " + e); 
      } 

      // log output for debugging 
      for (Map.Entry<String, Integer> 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); 
     } 
    } 
    } 

Peut-être que ces informations addtional à partir des journaux semble que cela pourrait être pertinent pour diagnostiquer correctement cette question:

"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 

Answer 1

Pour comprendre où exactement le mappeur est bloqué, jstack peut être utilisé [pour obtenir le vidage du thread]. Jstack est livré avec jdk et vous pouvez l'utiliser sur le processus de mappage bloqué comme suit.

Step0: Trouver le nom d'hôte dans lequel votre tâche de carte en cours d'exécution ont été et de faire une note de la task_id

Etape 1: se connecter au nœud et exécutez

ps aux | grep TASK_ID

identifier l'ID de processus et le nom d'utilisateur du processus qui commence avec/usr/java/jdk/bin/java

Etape 2: su au propriétaire du processus nom d'utilisateur

Etape 3: export java la maison et le chemin bin [exemple: export JAVA_HOME =/usr/java/jdk1.7.0_67 & & export PATH = $ JAVA_HOME/bin: $ PATH]

step4: remplacer pid avec pid obtenu à l'étape 1:

export PID = PID pour i dans $ (seq 1 10); fais écho "Jstack Iteration $ i"; jstack $ PID>/tmp/hungtask- hostname - $ {PID} .jstack. $ i; dormir 5s; fait goudron zcf hungtask.tar.gz/tmp/hungtask- hostname -. $ {PID} .jstack *

le hungtask.tar.gz contiendra le vidage de thread du processus pris à intervalles de 5 secondes pour dix fois. Vous devrez peut-être exécuter le script au moment où la tâche passe à l'état bloqué. Après cela, si vous pouvez télécharger hungtask.tar.gz à ce sujet, je peux voir et partager mon observation.

également à comprendre si le processus est en cours fréquent GC vous pouvez essayer la commande ci-dessous

jstat -gc -t PID STEP

PID est l'ID de processus du processus java pour surveiller STEP est le échantillon timestep

Vous pouvez coller le contenu du site Web http://nix-on.blogspot.in/2015/01/java-jstat-how-to-visualize-garbage.html pour comprendre si elle est en cours excessive GC