Return-Path: X-Original-To: apmail-hadoop-hdfs-user-archive@minotaur.apache.org Delivered-To: apmail-hadoop-hdfs-user-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id D5DAE9749 for ; Fri, 25 May 2012 08:54:01 +0000 (UTC) Received: (qmail 41135 invoked by uid 500); 25 May 2012 08:54:00 -0000 Delivered-To: apmail-hadoop-hdfs-user-archive@hadoop.apache.org Received: (qmail 41061 invoked by uid 500); 25 May 2012 08:53:59 -0000 Mailing-List: contact hdfs-user-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: hdfs-user@hadoop.apache.org Delivered-To: mailing list hdfs-user@hadoop.apache.org Received: (qmail 41036 invoked by uid 99); 25 May 2012 08:53:58 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 25 May 2012 08:53:58 +0000 X-ASF-Spam-Status: No, hits=2.2 required=5.0 tests=HTML_MESSAGE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: local policy) Received: from [141.51.167.101] (HELO gundel.cs.uni-kassel.de) (141.51.167.101) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 25 May 2012 08:53:50 +0000 Received: from localhost (localhost [127.0.0.1]) by gundel.cs.uni-kassel.de (Postfix) with ESMTP id AA3E744A3C3 for ; Fri, 25 May 2012 10:53:29 +0200 (CEST) X-Virus-Scanned: Debian amavisd-new at gundel.cs.uni-kassel.de Received: from gundel.cs.uni-kassel.de ([127.0.0.1]) by localhost (gundel.cs.uni-kassel.de [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id RobZm5j+LEhV for ; Fri, 25 May 2012 10:53:23 +0200 (CEST) Received: from [141.51.123.117] (fudd.cs.uni-kassel.de [141.51.123.117]) by gundel.cs.uni-kassel.de (Postfix) with ESMTPSA id EF4D744A3BD for ; Fri, 25 May 2012 10:53:22 +0200 (CEST) Message-ID: <4FBF4887.9020000@cs.uni-kassel.de> Date: Fri, 25 May 2012 10:53:27 +0200 From: =?ISO-8859-1?Q?Bj=F6rn-Elmar_Macek?= User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:12.0) Gecko/20120428 Thunderbird/12.0.1 MIME-Version: 1.0 To: hdfs-user@hadoop.apache.org Subject: Re: Hadoop Debugging in LocalMode (Breakpoints not reached) References: <40D0EF3A-DE4D-45D3-8630-44187A21988A@maprtech.com> <4FBB5F80.5030800@cs.uni-kassel.de> <4FBBA947.4040504@cs.uni-kassel.de> <4FBCA411.6060009@cs.uni-kassel.de> In-Reply-To: <4FBCA411.6060009@cs.uni-kassel.de> Content-Type: multipart/alternative; boundary="------------020601060702040405060008" This is a multi-part message in MIME format. --------------020601060702040405060008 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 8bit Although the reactions did not give me the feeling there was much interest in my case, i have found a "solution" and some reasons for my problem. You might be interested in the discussion on Stackoverflow: http://stackoverflow.com/questions/10720132/hadoop-reducer-is-waiting-for-mapper-inputs Am 23.05.2012 10:47, schrieb Bj�rn-Elmar Macek: > Ok, i have look at the logs some further and googled every tiny bit of > them, hoping to find an answer out there. > I fear that the following line nails my problem at a big scale: > > 12/05/22 01:30:21 INFO mapred.ReduceTask: > attempt_local_0001_r_000000_0 Need another 2 map output(s) > where 0 is already in progress > > I found several discussions to problems, that also had this line in > their logs. I have checked my code for the following: > > * All inputs are collected in the mapper (tho not all would be neccessary) > * The Comparators run well and return proper values for all inputs > * The Partitioner always returns proper values > > Please, i would really need a hint, to where i have to look. > Am 22.05.2012 16:57, schrieb Bj�rn-Elmar Macek: >> Hi Jayaseelan, >> >> thanks for the bump! ;) >> >> I have continued working on the problem, but with no further success. >> I emptied the log directory and started the debugging all over again, >> resulting in no new logfiles, so i guess the program did not run into >> serious problems. Also all the code other classes, namely ... >> >> * Mapper >> * Partitioner >> * OutputKeyComparatorClass >> >> is executed and can easily be debugged. Stil the Reducer and the >> OutputValueGroupingComparator do NOT work. After the execution of the >> comparisons made by OutputKeyComparatorClass i get alot of active >> processes in my debugging view in eclipse: >> >> OpenJDK Client VM[localhost:5002] >> Thread [main] (Running) >> Thread [Thread-2] (Running) >> Daemon Thread [communication thread] (Running) >> Thread [MapOutputCopier attempt_local_0001_r_000000_0.0] (Running) >> Daemon Thread [Thread for merging in memory files] (Running) >> Thread [MapOutputCopier attempt_local_0001_r_000000_0.4] (Running) >> Thread [MapOutputCopier attempt_local_0001_r_000000_0.3] (Running) >> Thread [MapOutputCopier attempt_local_0001_r_000000_0.1] (Running) >> Thread [MapOutputCopier attempt_local_0001_r_000000_0.2] (Running) >> Daemon Thread [Thread for merging on-disk files] (Running) >> Daemon Thread [Thread for polling Map Completion Events] (Running) >> >> And those processes are running, but obviously waiting for something, >> since no output is produced. And it is not due to the havy load of >> input data, since this is a 10 line csv file, which shouldnt make any >> problems. >> >> I somehow have the feeling that the framework cannot handle my >> classes, but i dont understand why. >> >> I would really appreciate a decent hint, how to fix that. >> >> Thanks you for your time and help! >> Bj�rn-Elmar >> Am 22.05.2012 12:38, schrieb Jayaseelan E: >>> >>> ------------------------------------------------------------------------ >>> *From:* Bj�rn-Elmar Macek [mailto:macek@cs.uni-kassel.de] >>> *Sent:* Tuesday, May 22, 2012 3:12 PM >>> *To:* hdfs-user@hadoop.apache.org >>> *Subject:* Hadoop Debugging in LocalMode (Breakpoints not reached) >>> >>> Hi there, >>> >>> >>> i am currently trying to get rid of bugs in my Hadoop program by >>> debugging it. Everything went fine til some point yesterday. I dont >>> know what exactly happened, but my program does not stop at >>> breakpoints within the Reducer and also not within the RawComparator >>> for the values which i do use for sorting my inputs in the >>> ReducerIterator. >>> (see the classes set for the conf below:) >>> >>> conf.setOutputValueGroupingComparator(TwitterValueGroupingComparator.class); >>> conf.setReducerClass(RetweetReducer.class); >>> >>> The log looks like this: >>> >>> Warning: $HADOOP_HOME is deprecated. >>> >>> Listening for transport dt_socket at address: 5002 >>> >>> 12/05/21 19:24:20 INFO util.NativeCodeLoader: Loaded the >>> native-hadoop library >>> >>> 12/05/21 19:24:20 WARN mapred.JobClient: Use GenericOptionsParser >>> for parsing the arguments. Applications should implement Tool for >>> the same. >>> >>> 12/05/21 19:24:20 WARN snappy.LoadSnappy: Snappy native library not >>> loaded >>> >>> 12/05/21 19:24:20 INFO mapred.FileInputFormat: Total input paths to >>> process : 2 >>> >>> 12/05/21 19:24:20 WARN conf.Configuration: >>> file:/tmp/hadoop-ema/mapred/local/localRunner/job_local_0001.xml:a >>> attempt to override final parameter: fs.default.name;Ignoring. >>> >>> 12/05/21 19:24:20 WARN conf.Configuration: >>> file:/tmp/hadoop-ema/mapred/local/localRunner/job_local_0001.xml:a >>> attempt to override final parameter: mapred.job.tracker;Ignoring. >>> >>> 12/05/21 19:24:20 INFO mapred.JobClient: Running job: job_local_0001 >>> >>> 12/05/21 19:24:20 INFO util.ProcessTree: setsid exited with exit code 0 >>> >>> 12/05/21 19:24:21 INFO mapred.Task:Using ResourceCalculatorPlugin : >>> org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1c4ff2c >>> >>> 12/05/21 19:24:21 INFO mapred.MapTask: numReduceTasks: 1 >>> >>> 12/05/21 19:24:21 INFO mapred.MapTask: io.sort.mb = 100 >>> >>> 12/05/21 19:24:22 INFO mapred.JobClient:map 0% reduce 0% >>> >>> 12/05/21 19:24:22 INFO mapred.MapTask: data buffer = 79691776/99614720 >>> >>> 12/05/21 19:24:22 INFO mapred.MapTask: record buffer = 262144/327680 >>> >>> 12/05/21 19:24:22 INFO mapred.MapTask: Starting flush of map output >>> >>> 12/05/21 19:24:22 INFO mapred.MapTask: Finished spill 0 >>> >>> 12/05/21 19:24:22 INFO mapred.Task: >>> Task:attempt_local_0001_m_000000_0 is done. And is in the process of >>> commiting >>> >>> 12/05/21 19:24:23 INFO mapred.LocalJobRunner: >>> file:/home/ema/INPUT-H/tweets_ext:0+968 >>> >>> 12/05/21 19:24:23 INFO mapred.Task: Task >>> 'attempt_local_0001_m_000000_0' done. >>> >>> 12/05/21 19:24:23 INFO mapred.Task:Using ResourceCalculatorPlugin : >>> org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1e8c585 >>> >>> 12/05/21 19:24:23 INFO mapred.MapTask: numReduceTasks: 1 >>> >>> 12/05/21 19:24:23 INFO mapred.MapTask: io.sort.mb = 100 >>> >>> 12/05/21 19:24:24 INFO mapred.MapTask: data buffer = 79691776/99614720 >>> >>> 12/05/21 19:24:24 INFO mapred.MapTask: record buffer = 262144/327680 >>> >>> 12/05/21 19:24:24 INFO mapred.MapTask: Starting flush of map output >>> >>> 12/05/21 19:24:24 INFO mapred.Task: >>> Task:attempt_local_0001_m_000001_0 is done. And is in the process of >>> commiting >>> >>> 12/05/21 19:24:24 INFO mapred.JobClient:map 100% reduce 0% >>> >>> 12/05/21 19:24:26 INFO mapred.LocalJobRunner: >>> file:/home/ema/INPUT-H/tweets~:0+0 >>> >>> 12/05/21 19:24:26 INFO mapred.Task: Task >>> 'attempt_local_0001_m_000001_0' done. >>> >>> 12/05/21 19:24:26 INFO mapred.Task:Using ResourceCalculatorPlugin : >>> org.apache.hadoop.util.LinuxResourceCalculatorPlugin@191e4c >>> >>> 12/05/21 19:24:26 INFO mapred.ReduceTask: ShuffleRamManager: >>> MemoryLimit=709551680, MaxSingleShuffleLimit=177387920 >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Need another 2 map output(s) where 0 >>> is already in progress >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Thread started: Thread for merging >>> on-disk files >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Thread waiting: Thread for merging >>> on-disk files >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 >>> dup hosts) >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Thread started: Thread for merging in >>> memory files >>> >>> 12/05/21 19:24:27 INFO mapred.ReduceTask: >>> attempt_local_0001_r_000000_0 Thread started: Thread for polling Map >>> Completion Events >>> >>> 12/05/21 19:24:32 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> 12/05/21 19:24:35 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> 12/05/21 19:24:42 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> 12/05/21 19:24:48 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> 12/05/21 19:24:51 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> 12/05/21 19:24:57 INFO mapred.LocalJobRunner: reduce > copy > >>> >>> ... etc ... >>> >>> Is there something i have missed? >>> >>> Thanks for your help in advance! >>> >>> Best regards, >>> Bj�rn-Elmar >>> >>> >> > --------------020601060702040405060008 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Although the reactions did not give me the feeling there was much interest in my case, i have found a "solution" and some reasons for my problem. You might be interested in the discussion on Stackoverflow:
http://stackoverflow.com/questions/10720132/hadoop-reducer-is-waiting-for-mapper-inputs


Am 23.05.2012 10:47, schrieb Björn-Elmar Macek:
Ok, i have look at the logs some further and googled every tiny bit of them, hoping to find an answer out there.
I fear that the following line nails my problem at a big scale:

12/05/22 01:30:21 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Need another 2 map output(s)
where 0 is already in progress

I found several discussions to problems, that also had this line in their logs. I have checked my code for the following:

* All inputs are collected in the mapper (tho not all would be neccessary)
* The Comparators run well and return proper values for all inputs
* The Partitioner always returns proper values

Please, i would really need a hint, to where i have to look.
Am 22.05.2012 16:57, schrieb Björn-Elmar Macek:
Hi Jayaseelan,

thanks for the bump! ;)

I have continued working on the problem, but with no further success. I emptied the log directory and started the debugging all over again, resulting in no new logfiles, so i guess the program did not run into serious problems. Also all the code other classes, namely ...

* Mapper
* Partitioner
* OutputKeyComparatorClass

is executed and can easily be debugged. Stil the Reducer and the OutputValueGroupingComparator do NOT work. After the execution of the comparisons made by OutputKeyComparatorClass i get alot of active processes in my debugging view in eclipse:

OpenJDK Client VM[localhost:5002]   
    Thread [main] (Running)   
    Thread [Thread-2] (Running)   
    Daemon Thread [communication thread] (Running)   
    Thread [MapOutputCopier attempt_local_0001_r_000000_0.0] (Running)   
    Daemon Thread [Thread for merging in memory files] (Running)   
    Thread [MapOutputCopier attempt_local_0001_r_000000_0.4] (Running)   
    Thread [MapOutputCopier attempt_local_0001_r_000000_0.3] (Running)   
    Thread [MapOutputCopier attempt_local_0001_r_000000_0.1] (Running)   
    Thread [MapOutputCopier attempt_local_0001_r_000000_0.2] (Running)   
    Daemon Thread [Thread for merging on-disk files] (Running)   
    Daemon Thread [Thread for polling Map Completion Events] (Running)   

And those processes are running, but obviously waiting for something, since no output is produced. And it is not due to the havy load of input data, since this is a 10 line csv file, which shouldnt make any problems.

I somehow have the feeling that the framework cannot handle my classes, but i dont understand why.

I would really appreciate a decent hint, how to fix that.

Thanks you for your time and help!
Björn-Elmar
Am 22.05.2012 12:38, schrieb Jayaseelan E:
 

From: Björn-Elmar Macek [mailto:macek@cs.uni-kassel.de]
Sent: Tuesday, May 22, 2012 3:12 PM
To: hdfs-user@hadoop.apache.org
Subject: Hadoop Debugging in LocalMode (Breakpoints not reached)

Hi there,


i am currently trying to get rid of bugs in my Hadoop program by debugging it. Everything went fine til some point yesterday. I dont know what exactly happened, but my program does not stop at breakpoints within the Reducer and also not within the RawComparator for the values which i do use for sorting my inputs in the ReducerIterator.
(see the classes set for the conf below:)

conf.setOutputValueGroupingComparator(TwitterValueGroupingComparator.class);
conf.setReducerClass(RetweetReducer.class);

The log looks like this:

Warning: $HADOOP_HOME is deprecated.

Listening for transport dt_socket at address: 5002

12/05/21 19:24:20 INFO util.NativeCodeLoader: Loaded the native-hadoop library

12/05/21 19:24:20 WARN mapred.JobClient: Use GenericOptionsParser for parsing the arguments. Applications should implement Tool for the same.

12/05/21 19:24:20 WARN snappy.LoadSnappy: Snappy native library not loaded

12/05/21 19:24:20 INFO mapred.FileInputFormat: Total input paths to process : 2

12/05/21 19:24:20 WARN conf.Configuration: file:/tmp/hadoop-ema/mapred/local/localRunner/job_local_0001.xml:a attempt to override final parameter: fs.default.name;  Ignoring.

12/05/21 19:24:20 WARN conf.Configuration: file:/tmp/hadoop-ema/mapred/local/localRunner/job_local_0001.xml:a attempt to override final parameter: mapred.job.tracker;  Ignoring.

12/05/21 19:24:20 INFO mapred.JobClient: Running job: job_local_0001

12/05/21 19:24:20 INFO util.ProcessTree: setsid exited with exit code 0

12/05/21 19:24:21 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1c4ff2c

12/05/21 19:24:21 INFO mapred.MapTask: numReduceTasks: 1

12/05/21 19:24:21 INFO mapred.MapTask: io.sort.mb = 100

12/05/21 19:24:22 INFO mapred.JobClient:  map 0% reduce 0%

12/05/21 19:24:22 INFO mapred.MapTask: data buffer = 79691776/99614720

12/05/21 19:24:22 INFO mapred.MapTask: record buffer = 262144/327680

12/05/21 19:24:22 INFO mapred.MapTask: Starting flush of map output

12/05/21 19:24:22 INFO mapred.MapTask: Finished spill 0

12/05/21 19:24:22 INFO mapred.Task: Task:attempt_local_0001_m_000000_0 is done. And is in the process of commiting

12/05/21 19:24:23 INFO mapred.LocalJobRunner: file:/home/ema/INPUT-H/tweets_ext:0+968

12/05/21 19:24:23 INFO mapred.Task: Task 'attempt_local_0001_m_000000_0' done.

12/05/21 19:24:23 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@1e8c585

12/05/21 19:24:23 INFO mapred.MapTask: numReduceTasks: 1

12/05/21 19:24:23 INFO mapred.MapTask: io.sort.mb = 100

12/05/21 19:24:24 INFO mapred.MapTask: data buffer = 79691776/99614720

12/05/21 19:24:24 INFO mapred.MapTask: record buffer = 262144/327680

12/05/21 19:24:24 INFO mapred.MapTask: Starting flush of map output

12/05/21 19:24:24 INFO mapred.Task: Task:attempt_local_0001_m_000001_0 is done. And is in the process of commiting

12/05/21 19:24:24 INFO mapred.JobClient:  map 100% reduce 0%

12/05/21 19:24:26 INFO mapred.LocalJobRunner: file:/home/ema/INPUT-H/tweets~:0+0

12/05/21 19:24:26 INFO mapred.Task: Task 'attempt_local_0001_m_000001_0' done.

12/05/21 19:24:26 INFO mapred.Task:  Using ResourceCalculatorPlugin : org.apache.hadoop.util.LinuxResourceCalculatorPlugin@191e4c

12/05/21 19:24:26 INFO mapred.ReduceTask: ShuffleRamManager: MemoryLimit=709551680, MaxSingleShuffleLimit=177387920

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Need another 2 map output(s) where 0 is already in progress

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Thread started: Thread for merging on-disk files

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Thread waiting: Thread for merging on-disk files

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Scheduled 0 outputs (0 slow hosts and0 dup hosts)

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Thread started: Thread for merging in memory files

12/05/21 19:24:27 INFO mapred.ReduceTask: attempt_local_0001_r_000000_0 Thread started: Thread for polling Map Completion Events

12/05/21 19:24:32 INFO mapred.LocalJobRunner: reduce > copy >

12/05/21 19:24:35 INFO mapred.LocalJobRunner: reduce > copy >

12/05/21 19:24:42 INFO mapred.LocalJobRunner: reduce > copy >

12/05/21 19:24:48 INFO mapred.LocalJobRunner: reduce > copy >

12/05/21 19:24:51 INFO mapred.LocalJobRunner: reduce > copy >

12/05/21 19:24:57 INFO mapred.LocalJobRunner: reduce > copy >

... etc ...

Is there something i have missed?

Thanks for your help in advance!

Best regards,
Björn-Elmar





--------------020601060702040405060008--