Mailing-List: contact core-dev-help@hadoop.apache.org; run by ezmlm
Precedence: bulk
Reply-To: core-dev@hadoop.apache.org
Message-ID: <1341860840.1224013184388.JavaMail.jira@brutus>
Date: Tue, 14 Oct 2008 12:39:44 -0700 (PDT)
From: "Devaraj Das (JIRA)" <jira@apache.org>
To: core-dev@hadoop.apache.org
Subject: [jira] Issue Comment Edited: (HADOOP-4396) sort on 400 nodes is now
 slower than in 18
In-Reply-To: <989949497.1223742224299.JavaMail.jira@brutus>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


    [ https://issues.apache.org/jira/browse/HADOOP-4396?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12639552#action_12639552 ] 

devaraj edited comment on HADOOP-4396 at 10/14/08 12:39 PM:
----------------------------------------------------------------

Raghu, I pasted a portion of the beginning of the task logs for one of the map tasks where the problem showed up. Notice the time when the map started running (15:05:15) and note the time when the first spill happened (15:13:17). The entire time duration (~8 minutes) was spent in consuming ~128MB of data from the dfs (and this happened to be a task that got scheduled on a data-local node). Quite unexpected since in the normal case it takes a few seconds... The strange thing is that it is not a node issue. So for this run of the sort400, on a particular node, a couple of maps exhibited this behavior but many ran normally.. And in a subsequent sort400 run, with the same dataset, *none*  of the maps scheduled on this node exhibited the problem!


2008-10-14 15:05:15,064 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=MAP, sessionId=
2008-10-14 15:05:15,156 INFO org.apache.hadoop.mapred.MapTask: numReduceTasks: 1741
2008-10-14 15:05:15,173 INFO org.apache.hadoop.mapred.MapTask: io.sort.mb = 128
2008-10-14 15:05:15,378 INFO org.apache.hadoop.mapred.MapTask: data buffer = 102005480/127506848
2008-10-14 15:05:15,379 INFO org.apache.hadoop.mapred.MapTask: record buffer = 335544/419430
2008-10-14 15:05:15,394 INFO org.apache.hadoop.util.NativeCodeLoader: Loaded the native-hadoop library
2008-10-14 15:05:15,396 INFO org.apache.hadoop.io.compress.LzoCodec: Successfully loaded & initialized native-lzo library
2008-10-14 15:05:15,591 INFO org.apache.hadoop.io.compress.zlib.ZlibFactory: Successfully loaded & initialized native-zlib library
2008-10-14 15:05:15,592 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,593 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,593 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,594 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:13:17,408 INFO org.apache.hadoop.mapred.MapTask: Spilling map output: buffer full= true

      was (Author: devaraj):
    Raghu, I pasted a portion of the beginning of the task logs for one of the map tasks where the problem showed up. Notice the time when the map started running (15:05:15) and note the time when the first spill happened (15:13:17). The entire time duration (~8 minutes) was spent in consuming ~128MB of data from the dfs (and this happened to be a task that got scheduled on a data-local node). Quite unexpected since in the normal case it takes a few seconds... The strange thing is that it is not a node issue. So for this run of the sort400, a couple of maps exhibited this behavior but many ran normally.. And in a subsequent sort400 run, with the same dataset, *none*  of the maps run on this node exhibited the problem!


2008-10-14 15:05:15,064 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=MAP, sessionId=
2008-10-14 15:05:15,156 INFO org.apache.hadoop.mapred.MapTask: numReduceTasks: 1741
2008-10-14 15:05:15,173 INFO org.apache.hadoop.mapred.MapTask: io.sort.mb = 128
2008-10-14 15:05:15,378 INFO org.apache.hadoop.mapred.MapTask: data buffer = 102005480/127506848
2008-10-14 15:05:15,379 INFO org.apache.hadoop.mapred.MapTask: record buffer = 335544/419430
2008-10-14 15:05:15,394 INFO org.apache.hadoop.util.NativeCodeLoader: Loaded the native-hadoop library
2008-10-14 15:05:15,396 INFO org.apache.hadoop.io.compress.LzoCodec: Successfully loaded & initialized native-lzo library
2008-10-14 15:05:15,591 INFO org.apache.hadoop.io.compress.zlib.ZlibFactory: Successfully loaded & initialized native-zlib library
2008-10-14 15:05:15,592 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,593 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,593 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:05:15,594 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
2008-10-14 15:13:17,408 INFO org.apache.hadoop.mapred.MapTask: Spilling map output: buffer full= true
  
> sort on 400 nodes is now slower than in 18
> ------------------------------------------
>
>                 Key: HADOOP-4396
>                 URL: https://issues.apache.org/jira/browse/HADOOP-4396
>             Project: Hadoop Core
>          Issue Type: Bug
>          Components: mapred
>    Affects Versions: 0.19.0
>            Reporter: Jothi Padmanabhan
>            Assignee: Jothi Padmanabhan
>            Priority: Blocker
>             Fix For: 0.19.0
>
>
> Sort on 400 nodes on  hadoop release 18 takes about 29 minutes, but with the 19 branch takes about 32 minutes. This behavior is consistent.

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.