[jira] [Updated] (TEZ-1562) DAGImpl commitOrAbortOutputs takes long time (300+ seconds) for reducer vertex with 4000+ tasks

["Rajesh Balamohan (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/TEZ-1562?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Rajesh Balamohan updated TEZ-1562:
----------------------------------
    Attachment: TEZ-1562-fileoutputcommitter-time.png
                TEZ-1562-job-runtime.png

- Tried a synthetic job which would read and store 32 GB of lineitem table (Mapper --> Reducer).
- Used hadoop 2.8 (Mapreduce-4815 got committed in 2.7 itself)
- Tried with "mapreduce.fileoutputcommitter.algorithm.version=1" and "mapreduce.fileoutputcommitter.algorithm.version=2".
- Attaching the graphs with both the configs.
- Basically, "mapreduce.fileoutputcommitter.algorithm.version=2" fixes the issue.

> DAGImpl commitOrAbortOutputs takes long time (300+ seconds) for reducer vertex with 4000+ tasks
> -----------------------------------------------------------------------------------------------
>
>                 Key: TEZ-1562
>                 URL: https://issues.apache.org/jira/browse/TEZ-1562
>             Project: Apache Tez
>          Issue Type: Bug
>            Reporter: Rajesh Balamohan
>              Labels: performance
>         Attachments: TEZ-1562-fileoutputcommitter-time.png, TEZ-1562-job-runtime.png
>
>
> M7 --> R1
> M2 --> R1
> I was running a job with 4000 reducers.  This is in non-session mode.
> At the end of the job, it took 300+ seconds just to commit().  
> It appears that its doing some cleanup work. But in session mode, this could lead to the following issue
> 1. Open session
> 2. Run small job1
> 3. Run large job1
> 4. Run small job2
> In this case, small job2 wouldn't even start running until large-job1's commit is over which would be in the order of 300+ seconds.  
> Please refer to the logs here, 
> 2014-09-09 17:58:20,422 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Vertex vertex_1409722953518_0143_1_02 completed., numCompletedVertices=3, numSuccessfulVertices=3, numFailedVertices=0, numKilledVertices=0, numVertices=3
> 2014-09-09 17:58:20,422 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Calling DAG commit/abort for dag: dag_1409722953518_0143_1
> 2014-09-09 17:58:20,426 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Committing output: Reducer_6_sink for vertex: vertex_1409722953518_0143_1_02
> 2014-09-09 18:03:25,207 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: No output committers for vertex: Map_7
> 2014-09-09 18:03:25,207 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: No output committers for vertex: Map_2
> 2014-09-09 18:03:25,207 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Patch : Time taken to commitOrAbortOutputs : 304784  <==== In milliseconds
> 2014-09-09 18:03:25,361 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Patch : Time taken to log jobhistory : 304938  <==== Cumulative number
> 2014-09-09 18:03:25,363 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: Patch : Time taken to handle DAGAppMasterEventDAGFinished : 304940 <==== Cumulative number
> 2014-09-09 18:03:25,363 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: DAG: dag_1409722953518_0143_1 finished with state: SUCCEEDED
> 2014-09-09 18:03:25,363 INFO [AsyncDispatcher event handler] org.apache.tez.dag.app.dag.impl.DAGImpl: dag_1409722953518_0143_1 transitioned from RUNNING to SUCCEEDED
> Should this operation be moved to a separate thread as the DAG is already marked as SUCCEEDED?



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)