Return-Path: 
 <user-return-2997-apmail-hadoop-common-user-archive=hadoop.apache.org@hadoop.apache.org>
X-Original-To: apmail-hadoop-common-user-archive@www.apache.org
Delivered-To: apmail-hadoop-common-user-archive@www.apache.org
Received: from mail.apache.org (hermes.apache.org [140.211.11.3])
	by minotaur.apache.org (Postfix) with SMTP id 75CE6E661
	for <apmail-hadoop-common-user-archive@www.apache.org>;
 Tue, 20 Nov 2012 13:44:40 +0000 (UTC)
Received: (qmail 21474 invoked by uid 500); 20 Nov 2012 13:44:35 -0000
Delivered-To: apmail-hadoop-common-user-archive@hadoop.apache.org
Received: (qmail 21266 invoked by uid 500); 20 Nov 2012 13:44:34 -0000
Mailing-List: contact user-help@hadoop.apache.org; run by ezmlm
Precedence: bulk
List-Help: <mailto:user-help@hadoop.apache.org>
List-Unsubscribe: <mailto:user-unsubscribe@hadoop.apache.org>
List-Post: <mailto:user@hadoop.apache.org>
List-Id: <user.hadoop.apache.org>
Reply-To: user@hadoop.apache.org
Delivered-To: mailing list user@hadoop.apache.org
Received: (qmail 21225 invoked by uid 99); 20 Nov 2012 13:44:33 -0000
Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136)
    by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 20 Nov 2012 13:44:33 +0000
X-ASF-Spam-Status: No, hits=1.5 required=5.0
	tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS
X-Spam-Check-By: apache.org
Received-SPF: pass (athena.apache.org: domain of Jan.Lukavsky@firma.seznam.cz
 designates 77.75.74.246 as permitted sender)
Received: from [77.75.74.246] (HELO posta.szn.cz) (77.75.74.246)
    by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 20 Nov 2012 13:44:26 +0000
Received: from [10.0.2.22] (10.0.2.22) by posta.szn.cz (10.0.3.149) with
 Microsoft SMTP Server id 14.2.298.4; Tue, 20 Nov 2012 14:44:03 +0100
Message-ID: <50AB8922.80608@firma.seznam.cz>
Date: Tue, 20 Nov 2012 14:44:02 +0100
From: =?ISO-8859-1?Q?Jan_Lukavsk=FD?= <jan.lukavsky@firma.seznam.cz>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
 rv:16.0) Gecko/20121028 Thunderbird/16.0.2
MIME-Version: 1.0
To: <user@hadoop.apache.org>
Subject: Inconsistent state in JobTracker (cdh)
Content-Type: multipart/alternative;
	boundary="------------060309090408020704010001"
X-Originating-IP: [10.0.2.22]
X-Virus-Checked: Checked by ClamAV on apache.org

--------------060309090408020704010001
Content-Type: text/plain; charset="ISO-8859-1"; format=flowed
Content-Transfer-Encoding: 7bit

Hi all,

we are time to time experiencing a little odd behavior of JobTracker 
(using cdh release, currently on cdh3u3, but I suppose this affects at 
least all cdh3 releases so far). What we are seeing is M/R job beeing 
stuck between map and reduce phase, with 100% maps completed but the web 
UI reports 1 running map task and since we 
have**mapred.reduce.slowstart.completed.maps set to 1.0 (because of 
better throughput of jobs) the reduce phase will never start and the job 
has to be killed. I have investigated this a bit and I think I have 
found the reason for this.

12/11/20 01:05:10 INFO mapred.JobInProgress: Task 
'attempt_201211011002_1852_m_007638_0' has completed 
task_201211011002_1852_m_007638 successfully.
12/11/20 01:05:10 WARN hdfs.DFSClient: DataStreamer Exception: 
org.apache.hadoop.ipc.RemoteException: 
org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException: No lease 
on <some output path> File does not exist. [Lease. Holder: 
DFSClient_408514838, pendingcreates: 1]
....
12/11/20 01:05:10 WARN hdfs.DFSClient: Error Recovery for block 
blk_-1434919284750099885_670717751 bad datanode[0] nodes == null
12/11/20 01:05:10 WARN hdfs.DFSClient: Could not get block locations. 
Source file "<some output path>" - Aborting...
12/11/20 01:05:10 INFO mapred.JobHistory: Logging failed for job 
job_201211011002_1852removing PrintWriter from FileManager
12/11/20 01:05:10 ERROR security.UserGroupInformation: 
PriviledgedActionException as:mapred (auth:SIMPLE) 
cause:java.io.IOException: java.util.ConcurrentModificationException
12/11/20 01:05:10 INFO ipc.Server: IPC Server handler 7 on 9001, call 
heartbeat(org.apache.hadoop.mapred.TaskTrackerStatus@1256e5f6, false, 
false, true, -17988) from 10.2.73.35:44969: error: java.io.IOException: 
java.util.ConcurrentModificationException


When I look to the source code for JobInProgress.completedTask(), I see 
the log about successful competion of the task, and after that, the 
logging in HDFS (JobHistory.Task.logFinished()). I suppose that if this 
call throws an exception (like in the case above), the call to 
completedTask() is aborted *before* the counters runningMapTasks and 
finishedMapTasks are updated accordingly. I created a heap dump of the 
JobTracker and I really found the counter runningMapTasks set to 1 and 
finishedMapTasks was equal to numMapTasks - 1.

Now, the question is, should this be handled in the JobTracker (say by 
moving the logging code after the counter manipulation)? Or should the 
TaskTracker re-report the completed task on error in JobTracker? What 
can cause the LeaseExpiredException? Should a JIRA be filled? :)

Thanks for comments,
  Jan



--------------060309090408020704010001
Content-Type: text/html; charset="ISO-8859-1"
Content-Transfer-Encoding: 7bit

<html>
  <head>

    <meta http-equiv="content-type" content="text/html; charset=ISO-8859-1">
  </head>
  <body text="#000000" bgcolor="#FFFFFF">
    Hi all,<br>
    <br>
    we are time to time experiencing a little odd behavior of JobTracker
    (using cdh release, currently on cdh3u3, but I suppose this affects
    at least all cdh3 releases so far). What we are seeing is M/R job
    beeing stuck between map and reduce phase, with 100% maps completed
    but the web UI reports 1 running map task and since we have<b> </b>mapred.reduce.slowstart.completed.maps
    set to 1.0 (because of better throughput of jobs) the reduce phase
    will never start and the job has to be killed. I have investigated
    this a bit and I think I have found the reason for this.<br>
    <br>
    12/11/20 01:05:10 INFO mapred.JobInProgress: Task
    'attempt_201211011002_1852_m_007638_0' has completed
    task_201211011002_1852_m_007638 successfully.<br>
    12/11/20 01:05:10 WARN hdfs.DFSClient: DataStreamer Exception:
    org.apache.hadoop.ipc.RemoteException:
    org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException: No
    lease on &lt;some output path&gt; File does not exist. [Lease.&nbsp;
    Holder: DFSClient_408514838, pendingcreates: 1]<br>
    ....<br>
    12/11/20 01:05:10 WARN hdfs.DFSClient: Error Recovery for block
    blk_-1434919284750099885_670717751 bad datanode[0] nodes == null<br>
    12/11/20 01:05:10 WARN hdfs.DFSClient: Could not get block
    locations. Source file "&lt;some output path&gt;" - Aborting...<br>
    12/11/20 01:05:10 INFO mapred.JobHistory: Logging failed for job
    job_201211011002_1852removing PrintWriter from FileManager<br>
    12/11/20 01:05:10 ERROR security.UserGroupInformation:
    PriviledgedActionException as:mapred (auth:SIMPLE)
    cause:java.io.IOException: java.util.ConcurrentModificationException<br>
    12/11/20 01:05:10 INFO ipc.Server: IPC Server handler 7 on 9001,
    call heartbeat(org.apache.hadoop.mapred.TaskTrackerStatus@1256e5f6,
    false, false, true, -17988) from 10.2.73.35:44969: error:
    java.io.IOException: java.util.ConcurrentModificationException<br>
    <br>
    <br>
    When I look to the source code for JobInProgress.completedTask(), I
    see the log about successful competion of the task, and after that,
    the logging in HDFS (JobHistory.Task.logFinished()). I suppose that
    if this call throws an exception (like in the case above), the call
    to completedTask() is aborted *before* the counters runningMapTasks
    and finishedMapTasks are updated accordingly. I created a heap dump
    of the JobTracker and I really found the counter runningMapTasks set
    to 1 and finishedMapTasks was equal to numMapTasks - 1.<br>
    <br>
    Now, the question is, should this be handled in the JobTracker (say
    by moving the logging code after the counter manipulation)? Or
    should the TaskTracker re-report the completed task on error in
    JobTracker? What can cause the LeaseExpiredException? Should a JIRA
    be filled? :)<br>
    <br>
    Thanks for comments,<br>
    &nbsp;Jan<br>
    <br>
    <br>
    <pre class="moz-signature" cols="72">
</pre>
  </body>
</html>

--------------060309090408020704010001--