You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@tez.apache.org by Amit Tewari <am...@gmail.com> on 2014/03/26 01:56:07 UTC
No seeing tez based speedup
I tried to run orderedwordcount example with 3 inputs and outputs
expecting to see speed up in second and third DAG execution. However I
found all the executions took roughly the same amount of time. Its more
concerning that I used the same input for every iteration.
Full log is included below.
Not sure where to start debugging this. Any pointers ?
-A
[hive@hdpmaster2 ~]$hadoop jar
/root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar
orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh
/tmp/out2
14/03/26 00:29:40 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:29:41 INFO examples.OrderedWordCount: Creating Tez Session
14/03/26 00:29:41 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:29:41 INFO Configuration.deprecation: fs.default.name is
deprecated. Instead, use fs.defaultFS
14/03/26 00:29:42 INFO impl.YarnClientImpl: Submitted application
application_1395361607432_0043 to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:29:42 INFO examples.OrderedWordCount: Created Tez Session
14/03/26 00:29:42 INFO examples.OrderedWordCount: Running
OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh,
outputPath=/tmp/out1
14/03/26 00:29:42 INFO examples.OrderedWordCount: Waiting for TezSession
to get into ready state
14/03/26 00:29:48 INFO examples.OrderedWordCount: Submitting DAG to Tez
Session, dagIndex=1
14/03/26 00:29:48 INFO client.TezSession: Submitting dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0043
14/03/26 00:29:49 INFO client.TezSession: Submitted dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_1
14/03/26 00:29:49 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:29:49 INFO examples.OrderedWordCount: Submitted DAG to Tez
Session, dagIndex=1
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 75%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 100%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: SUCCEEDED Progress: 100%
VertexStatus: VertexName: initialmap Progress: 100%
Vertex Counters for initialmap: Counters: 21
File System Counters
FILE: BYTES_READ=0
FILE: BYTES_WRITTEN=2099
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=1
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=169
MAP_OUTPUT_BYTES=1693
MAP_OUTPUT_MATERIALIZED_BYTES=2043
SPILLED_RECORDS=169
GC_TIME_MILLIS=232
CPU_MILLISECONDS=-1190
PHYSICAL_MEMORY_BYTES=248156160
VIRTUAL_MEMORY_BYTES=906416128
COMMITTED_HEAP_BYTES=202248192
File Input Format Counters
Bytes Read=0
VertexStatus: VertexName: intermediate_reducer Progress: 100%
Vertex Counters for intermediate_reducer: Counters: 32
File System Counters
FILE: BYTES_READ=2043
FILE: BYTES_WRITTEN=3606
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=0
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
MAP_OUTPUT_BYTES=1259
MAP_OUTPUT_MATERIALIZED_BYTES=1499
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=114
REDUCE_SHUFFLE_BYTES=2043
REDUCE_INPUT_RECORDS=169
SPILLED_RECORDS=283
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=926
CPU_MILLISECONDS=-550
PHYSICAL_MEMORY_BYTES=433655808
VIRTUAL_MEMORY_BYTES=2449571840
COMMITTED_HEAP_BYTES=326901760
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
VertexStatus: VertexName: finalreduce Progress: 100%
Vertex Counters for finalreduce: Counters: 31
File System Counters
FILE: BYTES_READ=1493
FILE: BYTES_WRITTEN=1493
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=3
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=6
REDUCE_SHUFFLE_BYTES=1499
REDUCE_INPUT_RECORDS=114
SPILLED_RECORDS=114
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=8
CPU_MILLISECONDS=-6720
PHYSICAL_MEMORY_BYTES=211603456
VIRTUAL_MEMORY_BYTES=1228931072
COMMITTED_HEAP_BYTES=163450880
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Output Format Counters
Bytes Written=1032
DAG Counters: Counters: 36
org.apache.tez.common.counters.DAGCounter
TOTAL_LAUNCHED_TASKS=4
File System Counters
FILE: BYTES_READ=3536
FILE: BYTES_WRITTEN=7198
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=4
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=397
MAP_OUTPUT_BYTES=2952
MAP_OUTPUT_MATERIALIZED_BYTES=3542
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=120
REDUCE_SHUFFLE_BYTES=3542
REDUCE_INPUT_RECORDS=283
SPILLED_RECORDS=566
SHUFFLED_MAPS=4
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=4
GC_TIME_MILLIS=1166
CPU_MILLISECONDS=-8460
PHYSICAL_MEMORY_BYTES=893415424
VIRTUAL_MEMORY_BYTES=4584919040
COMMITTED_HEAP_BYTES=692600832
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=0
File Output Format Counters
Bytes Written=1032
14/03/26 00:30:19 INFO examples.OrderedWordCount: DAG 1 completed.
FinalState=SUCCEEDED
14/03/26 00:30:19 INFO examples.OrderedWordCount: Running
OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh,
outputPath=/tmp/out2
14/03/26 00:30:19 INFO examples.OrderedWordCount: Waiting for TezSession
to get into ready state
14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitting DAG to Tez
Session, dagIndex=2
14/03/26 00:30:19 INFO client.TezSession: Submitting dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0043
14/03/26 00:30:19 INFO client.TezSession: Submitted dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_2
14/03/26 00:30:19 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitted DAG to Tez
Session, dagIndex=2
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 75%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 100%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: SUCCEEDED Progress: 100%
VertexStatus: VertexName: initialmap Progress: 100%
Vertex Counters for initialmap: Counters: 21
File System Counters
FILE: BYTES_READ=0
FILE: BYTES_WRITTEN=2099
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=1
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=169
MAP_OUTPUT_BYTES=1693
MAP_OUTPUT_MATERIALIZED_BYTES=2043
SPILLED_RECORDS=169
GC_TIME_MILLIS=194
CPU_MILLISECONDS=-650
PHYSICAL_MEMORY_BYTES=263884800
VIRTUAL_MEMORY_BYTES=906760192
COMMITTED_HEAP_BYTES=202248192
File Input Format Counters
Bytes Read=0
VertexStatus: VertexName: intermediate_reducer Progress: 100%
Vertex Counters for intermediate_reducer: Counters: 32
File System Counters
FILE: BYTES_READ=2043
FILE: BYTES_WRITTEN=3606
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=0
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
MAP_OUTPUT_BYTES=1259
MAP_OUTPUT_MATERIALIZED_BYTES=1499
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=114
REDUCE_SHUFFLE_BYTES=2043
REDUCE_INPUT_RECORDS=169
SPILLED_RECORDS=283
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=738
CPU_MILLISECONDS=-380
PHYSICAL_MEMORY_BYTES=453808128
VIRTUAL_MEMORY_BYTES=2449682432
COMMITTED_HEAP_BYTES=326901760
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
VertexStatus: VertexName: finalreduce Progress: 100%
Vertex Counters for finalreduce: Counters: 31
File System Counters
FILE: BYTES_READ=1493
FILE: BYTES_WRITTEN=1493
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=3
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=6
REDUCE_SHUFFLE_BYTES=1499
REDUCE_INPUT_RECORDS=114
SPILLED_RECORDS=114
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=10
CPU_MILLISECONDS=-6130
PHYSICAL_MEMORY_BYTES=230133760
VIRTUAL_MEMORY_BYTES=1229070336
COMMITTED_HEAP_BYTES=163450880
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Output Format Counters
Bytes Written=1032
DAG Counters: Counters: 36
org.apache.tez.common.counters.DAGCounter
TOTAL_LAUNCHED_TASKS=4
File System Counters
FILE: BYTES_READ=3536
FILE: BYTES_WRITTEN=7198
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=4
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=397
MAP_OUTPUT_BYTES=2952
MAP_OUTPUT_MATERIALIZED_BYTES=3542
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=120
REDUCE_SHUFFLE_BYTES=3542
REDUCE_INPUT_RECORDS=283
SPILLED_RECORDS=566
SHUFFLED_MAPS=4
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=4
GC_TIME_MILLIS=942
CPU_MILLISECONDS=-7160
PHYSICAL_MEMORY_BYTES=947826688
VIRTUAL_MEMORY_BYTES=4585512960
COMMITTED_HEAP_BYTES=692600832
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=0
File Output Format Counters
Bytes Written=1032
14/03/26 00:30:49 INFO examples.OrderedWordCount: DAG 2 completed.
FinalState=SUCCEEDED
14/03/26 00:30:49 INFO client.TezSession: Shutting down Tez Session,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0043
[hive@hdpmaster2 ~]$ hdfs dfs -rm -r /tmp/out*
14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash
configuration: Deletion interval = 21600000 minutes, Emptier interval =
0 minutes.
Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out1' to trash at:
hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash
configuration: Deletion interval = 21600000 minutes, Emptier interval =
0 minutes.
Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out2' to trash at:
hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
[hive@hdpmaster2 ~]$ hadoop jar
/root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar
orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh
/tmp/out2 /tmp/wrap_ooziedb.sh /tmp/out3
14/03/26 00:31:11 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:31:12 INFO examples.OrderedWordCount: Creating Tez Session
14/03/26 00:31:12 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:31:12 INFO Configuration.deprecation: fs.default.name is
deprecated. Instead, use fs.defaultFS
14/03/26 00:31:13 INFO impl.YarnClientImpl: Submitted application
application_1395361607432_0044 to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:31:13 INFO examples.OrderedWordCount: Created Tez Session
14/03/26 00:31:13 INFO examples.OrderedWordCount: Running
OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh,
outputPath=/tmp/out1
14/03/26 00:31:13 INFO examples.OrderedWordCount: Waiting for TezSession
to get into ready state
14/03/26 00:31:20 INFO examples.OrderedWordCount: Submitting DAG to Tez
Session, dagIndex=1
14/03/26 00:31:20 INFO client.TezSession: Submitting dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044
14/03/26 00:31:21 INFO client.TezSession: Submitted dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_1
14/03/26 00:31:21 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:31:21 INFO examples.OrderedWordCount: Submitted DAG to Tez
Session, dagIndex=1
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 75%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 100%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: SUCCEEDED Progress: 100%
VertexStatus: VertexName: initialmap Progress: 100%
Vertex Counters for initialmap: Counters: 21
File System Counters
FILE: BYTES_READ=0
FILE: BYTES_WRITTEN=2099
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=1
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=169
MAP_OUTPUT_BYTES=1693
MAP_OUTPUT_MATERIALIZED_BYTES=2043
SPILLED_RECORDS=169
GC_TIME_MILLIS=95
CPU_MILLISECONDS=-1100
PHYSICAL_MEMORY_BYTES=263622656
VIRTUAL_MEMORY_BYTES=906416128
COMMITTED_HEAP_BYTES=202248192
File Input Format Counters
Bytes Read=0
VertexStatus: VertexName: intermediate_reducer Progress: 100%
Vertex Counters for intermediate_reducer: Counters: 32
File System Counters
FILE: BYTES_READ=2043
FILE: BYTES_WRITTEN=3606
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=0
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
MAP_OUTPUT_BYTES=1259
MAP_OUTPUT_MATERIALIZED_BYTES=1499
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=114
REDUCE_SHUFFLE_BYTES=2043
REDUCE_INPUT_RECORDS=169
SPILLED_RECORDS=283
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=456
CPU_MILLISECONDS=-1050
PHYSICAL_MEMORY_BYTES=451112960
VIRTUAL_MEMORY_BYTES=2449186816
COMMITTED_HEAP_BYTES=326901760
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
VertexStatus: VertexName: finalreduce Progress: 100%
Vertex Counters for finalreduce: Counters: 31
File System Counters
FILE: BYTES_READ=1493
FILE: BYTES_WRITTEN=1493
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=3
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=6
REDUCE_SHUFFLE_BYTES=1499
REDUCE_INPUT_RECORDS=114
SPILLED_RECORDS=114
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=6
CPU_MILLISECONDS=-5130
PHYSICAL_MEMORY_BYTES=227819520
VIRTUAL_MEMORY_BYTES=1228775424
COMMITTED_HEAP_BYTES=163450880
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Output Format Counters
Bytes Written=1032
DAG Counters: Counters: 36
org.apache.tez.common.counters.DAGCounter
TOTAL_LAUNCHED_TASKS=4
File System Counters
FILE: BYTES_READ=3536
FILE: BYTES_WRITTEN=7198
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=4
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=397
MAP_OUTPUT_BYTES=2952
MAP_OUTPUT_MATERIALIZED_BYTES=3542
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=120
REDUCE_SHUFFLE_BYTES=3542
REDUCE_INPUT_RECORDS=283
SPILLED_RECORDS=566
SHUFFLED_MAPS=4
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=4
GC_TIME_MILLIS=557
CPU_MILLISECONDS=-7280
PHYSICAL_MEMORY_BYTES=942555136
VIRTUAL_MEMORY_BYTES=4584378368
COMMITTED_HEAP_BYTES=692600832
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=0
File Output Format Counters
Bytes Written=1032
14/03/26 00:31:45 INFO examples.OrderedWordCount: DAG 1 completed.
FinalState=SUCCEEDED
14/03/26 00:31:45 INFO examples.OrderedWordCount: Running
OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh,
outputPath=/tmp/out2
14/03/26 00:31:45 INFO examples.OrderedWordCount: Waiting for TezSession
to get into ready state
14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitting DAG to Tez
Session, dagIndex=2
14/03/26 00:31:45 INFO client.TezSession: Submitting dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044
14/03/26 00:31:45 INFO client.TezSession: Submitted dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_2
14/03/26 00:31:45 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitted DAG to Tez
Session, dagIndex=2
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 75%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 100%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: SUCCEEDED Progress: 100%
VertexStatus: VertexName: initialmap Progress: 100%
Vertex Counters for initialmap: Counters: 21
File System Counters
FILE: BYTES_READ=0
FILE: BYTES_WRITTEN=2099
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=1
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=169
MAP_OUTPUT_BYTES=1693
MAP_OUTPUT_MATERIALIZED_BYTES=2043
SPILLED_RECORDS=169
GC_TIME_MILLIS=94
CPU_MILLISECONDS=-1080
PHYSICAL_MEMORY_BYTES=254423040
VIRTUAL_MEMORY_BYTES=906416128
COMMITTED_HEAP_BYTES=202248192
File Input Format Counters
Bytes Read=0
VertexStatus: VertexName: intermediate_reducer Progress: 100%
Vertex Counters for intermediate_reducer: Counters: 32
File System Counters
FILE: BYTES_READ=2043
FILE: BYTES_WRITTEN=3606
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=0
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
MAP_OUTPUT_BYTES=1259
MAP_OUTPUT_MATERIALIZED_BYTES=1499
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=114
REDUCE_SHUFFLE_BYTES=2043
REDUCE_INPUT_RECORDS=169
SPILLED_RECORDS=283
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=504
CPU_MILLISECONDS=-990
PHYSICAL_MEMORY_BYTES=450039808
VIRTUAL_MEMORY_BYTES=2449768448
COMMITTED_HEAP_BYTES=326901760
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
VertexStatus: VertexName: finalreduce Progress: 100%
Vertex Counters for finalreduce: Counters: 31
File System Counters
FILE: BYTES_READ=1493
FILE: BYTES_WRITTEN=1493
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=3
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=6
REDUCE_SHUFFLE_BYTES=1499
REDUCE_INPUT_RECORDS=114
SPILLED_RECORDS=114
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=6
CPU_MILLISECONDS=-5170
PHYSICAL_MEMORY_BYTES=229675008
VIRTUAL_MEMORY_BYTES=1228996608
COMMITTED_HEAP_BYTES=163450880
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Output Format Counters
Bytes Written=1032
DAG Counters: Counters: 36
org.apache.tez.common.counters.DAGCounter
TOTAL_LAUNCHED_TASKS=4
File System Counters
FILE: BYTES_READ=3536
FILE: BYTES_WRITTEN=7198
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=4
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=397
MAP_OUTPUT_BYTES=2952
MAP_OUTPUT_MATERIALIZED_BYTES=3542
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=120
REDUCE_SHUFFLE_BYTES=3542
REDUCE_INPUT_RECORDS=283
SPILLED_RECORDS=566
SHUFFLED_MAPS=4
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=4
GC_TIME_MILLIS=604
CPU_MILLISECONDS=-7240
PHYSICAL_MEMORY_BYTES=934137856
VIRTUAL_MEMORY_BYTES=4585181184
COMMITTED_HEAP_BYTES=692600832
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=0
File Output Format Counters
Bytes Written=1032
14/03/26 00:32:11 INFO examples.OrderedWordCount: DAG 2 completed.
FinalState=SUCCEEDED
14/03/26 00:32:11 INFO examples.OrderedWordCount: Running
OrderedWordCount DAG, dagIndex=3, inputPath=/tmp/wrap_ooziedb.sh,
outputPath=/tmp/out3
14/03/26 00:32:11 INFO examples.OrderedWordCount: Waiting for TezSession
to get into ready state
14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitting DAG to Tez
Session, dagIndex=3
14/03/26 00:32:11 INFO client.TezSession: Submitting dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044
14/03/26 00:32:11 INFO client.TezSession: Submitted dag to TezSession,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_3
14/03/26 00:32:11 INFO client.RMProxy: Connecting to ResourceManager at
hdpmaster2.hdp.hadoop/10.178.26.162:8050
14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitted DAG to Tez
Session, dagIndex=3
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 0%
VertexStatus: VertexName: initialmap Progress: 0%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 25%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 0%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 50%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 50%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: RUNNING Progress: 75%
VertexStatus: VertexName: initialmap Progress: 100%
VertexStatus: VertexName: intermediate_reducer Progress: 100%
VertexStatus: VertexName: finalreduce Progress: 0%
DAG: State: SUCCEEDED Progress: 100%
VertexStatus: VertexName: initialmap Progress: 100%
Vertex Counters for initialmap: Counters: 21
File System Counters
FILE: BYTES_READ=0
FILE: BYTES_WRITTEN=2099
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=1
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=169
MAP_OUTPUT_BYTES=1693
MAP_OUTPUT_MATERIALIZED_BYTES=2043
SPILLED_RECORDS=169
GC_TIME_MILLIS=105
CPU_MILLISECONDS=-1030
PHYSICAL_MEMORY_BYTES=266383360
VIRTUAL_MEMORY_BYTES=906416128
COMMITTED_HEAP_BYTES=202248192
File Input Format Counters
Bytes Read=0
VertexStatus: VertexName: intermediate_reducer Progress: 100%
Vertex Counters for intermediate_reducer: Counters: 32
File System Counters
FILE: BYTES_READ=2043
FILE: BYTES_WRITTEN=3606
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=0
HDFS: READ_OPS=0
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=0
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
MAP_OUTPUT_BYTES=1259
MAP_OUTPUT_MATERIALIZED_BYTES=1499
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=114
REDUCE_SHUFFLE_BYTES=2043
REDUCE_INPUT_RECORDS=169
SPILLED_RECORDS=283
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=385
CPU_MILLISECONDS=-1090
PHYSICAL_MEMORY_BYTES=432283648
VIRTUAL_MEMORY_BYTES=2449825792
COMMITTED_HEAP_BYTES=326901760
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
VertexStatus: VertexName: finalreduce Progress: 100%
Vertex Counters for finalreduce: Counters: 31
File System Counters
FILE: BYTES_READ=1493
FILE: BYTES_WRITTEN=1493
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=0
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=3
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_OUTPUT_RECORDS=114
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=6
REDUCE_SHUFFLE_BYTES=1499
REDUCE_INPUT_RECORDS=114
SPILLED_RECORDS=114
SHUFFLED_MAPS=2
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=2
GC_TIME_MILLIS=6
CPU_MILLISECONDS=-5240
PHYSICAL_MEMORY_BYTES=225894400
VIRTUAL_MEMORY_BYTES=1228943360
COMMITTED_HEAP_BYTES=163450880
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Output Format Counters
Bytes Written=1032
DAG Counters: Counters: 36
org.apache.tez.common.counters.DAGCounter
TOTAL_LAUNCHED_TASKS=4
File System Counters
FILE: BYTES_READ=3536
FILE: BYTES_WRITTEN=7198
FILE: READ_OPS=0
FILE: LARGE_READ_OPS=0
FILE: WRITE_OPS=0
HDFS: BYTES_READ=1029
HDFS: BYTES_WRITTEN=1032
HDFS: READ_OPS=4
HDFS: LARGE_READ_OPS=0
HDFS: WRITE_OPS=2
org.apache.tez.common.counters.TaskCounter
MAP_INPUT_RECORDS=31
MAP_OUTPUT_RECORDS=397
MAP_OUTPUT_BYTES=2952
MAP_OUTPUT_MATERIALIZED_BYTES=3542
COMBINE_INPUT_RECORDS=0
REDUCE_INPUT_GROUPS=120
REDUCE_SHUFFLE_BYTES=3542
REDUCE_INPUT_RECORDS=283
SPILLED_RECORDS=566
SHUFFLED_MAPS=4
FAILED_SHUFFLE=0
MERGED_MAP_OUTPUTS=4
GC_TIME_MILLIS=496
CPU_MILLISECONDS=-7360
PHYSICAL_MEMORY_BYTES=924561408
VIRTUAL_MEMORY_BYTES=4585185280
COMMITTED_HEAP_BYTES=692600832
Shuffle Errors
BAD_ID=0
CONNECTION=0
IO_ERROR=0
WRONG_LENGTH=0
WRONG_MAP=0
WRONG_REDUCE=0
File Input Format Counters
Bytes Read=0
File Output Format Counters
Bytes Written=1032
14/03/26 00:32:36 INFO examples.OrderedWordCount: DAG 3 completed.
FinalState=SUCCEEDED
14/03/26 00:32:37 INFO client.TezSession: Shutting down Tez Session,
sessionName=OrderedWordCountSession,
applicationId=application_1395361607432_0044
[hive@hdpmaster2 ~]$
Re: No seeing tez based speedup
Posted by Hitesh Shah <hi...@apache.org>.
The short answer is container re-use. Launching new containers in YARN and launching new JVMs is time consuming especially when trying to do this multiple times for a the job that is of a short duration.
Now, considering a case where a map task needs 512 MB containers with java opts set to -Xmx300m and a reduce needs 1024 m with java opts set to -Xmx600m. Tez will try to re-use containers as much as possible. If there is a container with equal or higher YARN resources allocated to it, it will re-use the container. However, if the java opts does not match, we do not re-use the container as trying to figure out if the java opts are compatible is not easy to figure out.
For a job which has 1000s of tasks but each task takes a short time, the container re-use benefits can be huge. For a job that has a small no. of tasks but each task's duration is high, container re-use benefits are less.
thanks
-- Hitesh
On Mar 26, 2014, at 11:13 AM, Amit Tewari wrote:
> Ok that did the trick.
>
> I am going to try it with lower (but equal) memory setting for both now because the file I am trying to process is literally 1K in size. I will send out an email when I am done.
>
> Would you mind pointing out as to why keeping the memory setting equal affects the performance so much ? Conceptually I am not sure why it would. I am sure it would be helpful for everybody on this list to know.
>
> -A
>
> On 3/26/14 10:23 AM, Hitesh Shah wrote:
>> Try the following:
>>
>> Change map.memory.mb to 683 ( to match reduce )
>> Also change map java opts to Xmx546m ( to match reduce ).
>>
>> The DEBUG log level kicks in for the application master logs. You can retrieve those via "yarn logs -applicationId <appId>"
>>
>> -- Hitesh
>>
>> On Mar 26, 2014, at 10:12 AM, Amit Tewari wrote:
>>
>>> 341 (map), 683 (reduce)
>>>> - mapreduce.map.java.opts, mapreduce.reduce.java.opts
>>> -Xmx273m (map), -Xmx546m (reduce)
>
Re: No seeing tez based speedup
Posted by Amit Tewari <am...@gmail.com>.
Ok that did the trick.
I am going to try it with lower (but equal) memory setting for both now
because the file I am trying to process is literally 1K in size. I will
send out an email when I am done.
Would you mind pointing out as to why keeping the memory setting equal
affects the performance so much ? Conceptually I am not sure why it
would. I am sure it would be helpful for everybody on this list to know.
-A
On 3/26/14 10:23 AM, Hitesh Shah wrote:
> Try the following:
>
> Change map.memory.mb to 683 ( to match reduce )
> Also change map java opts to Xmx546m ( to match reduce ).
>
> The DEBUG log level kicks in for the application master logs. You can retrieve those via "yarn logs -applicationId <appId>"
>
> -- Hitesh
>
> On Mar 26, 2014, at 10:12 AM, Amit Tewari wrote:
>
>> 341 (map), 683 (reduce)
>>> - mapreduce.map.java.opts, mapreduce.reduce.java.opts
>> -Xmx273m (map), -Xmx546m (reduce)
Re: No seeing tez based speedup
Posted by Hitesh Shah <hi...@apache.org>.
Try the following:
Change map.memory.mb to 683 ( to match reduce )
Also change map java opts to Xmx546m ( to match reduce ).
The DEBUG log level kicks in for the application master logs. You can retrieve those via "yarn logs -applicationId <appId>"
-- Hitesh
On Mar 26, 2014, at 10:12 AM, Amit Tewari wrote:
> 341 (map), 683 (reduce)
>> - mapreduce.map.java.opts, mapreduce.reduce.java.opts
> -Xmx273m (map), -Xmx546m (reduce)
Re: No seeing tez based speedup
Posted by Amit Tewari <am...@gmail.com>.
Comments included
-A
On 3/26/14 9:47 AM, Hitesh Shah wrote:
> Hello Amit,
>
> Some initial questions:
> - are you running this on a single node?
Its a multi-node cluster. 3 slaves 2 masters. Basically same set up as
here http://hortonworks.com/kb/ambari-on-ec2/
> - if yes, what are the settings in mapred-site for the following:
> - mapreduce.map.memory.mb, mapreduce.reduce.memory.mb
341 (map), 683 (reduce)
> - mapreduce.map.java.opts, mapreduce.reduce.java.opts
-Xmx273m (map), -Xmx546m (reduce)
>
> The reason the above may affect your job is how containers are re-used. If the map and reduce settings are different, containers may not get re-used and if your cluster is not big enough, it may end up releasing containers to get containers for the next stage. This will reduce the perf benefits of re-using the containers used by the previous DAG.
>
> Also, could you provide a copy of your tez-site.xml?
Its pretty vanilla just with one property
<?xml version="1.0"?>
<?xml-stylesheet type="text/xsl" href="configuration.xsl"?>
<!-- Put site-specific property overrides in this file. -->
<configuration xmlns:xi="http://www.w3.org/2001/XInclude">
<!-- Tez properties -->
<property>
<name>tez.lib.uris</name>
<value>${fs.default.name}/apps/tez-0.3.0-incubating,${fs.default.name}/apps/tez-0.3.0-incubating/lib/</value>
</property>
</configuration>
> And, if possible, try the same run again but with tez.am.log.level set to DEBUG in tez-site.xml
Ok new tez-site.xml looks like following but I don't see any debug logs.
I checked by running "hadoop classpath" that the right directory with
tez-site.xml is in the hadoop classpath. Logs attached
<configuration>
<property>
<name>tez.lib.uris</name>
<value>${fs.default.name}/apps/tez-0.3.0-incubating,${fs.default.name}/apps/tez-0.3.0-incubating/lib/</value>
</property>
<property>
<name>tez.am.log.level</name>
<value>DEBUG</value>
</property>
</configuration>
>
> thanks
> -- Hitesh
>
> On Mar 25, 2014, at 5:56 PM, Amit Tewari wrote:
>
>> I tried to run orderedwordcount example with 3 inputs and outputs expecting to see speed up in second and third DAG execution. However I found all the executions took roughly the same amount of time. Its more concerning that I used the same input for every iteration.
>>
>> Full log is included below.
>>
>> Not sure where to start debugging this. Any pointers ?
>>
>>
>> -A
>>
>>
>> [hive@hdpmaster2 ~]$hadoop jar /root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh /tmp/out2
>> 14/03/26 00:29:40 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:29:41 INFO examples.OrderedWordCount: Creating Tez Session
>> 14/03/26 00:29:41 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:29:41 INFO Configuration.deprecation: fs.default.name is deprecated. Instead, use fs.defaultFS
>> 14/03/26 00:29:42 INFO impl.YarnClientImpl: Submitted application application_1395361607432_0043 to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Created Tez Session
>> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out1
>> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
>> 14/03/26 00:29:48 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=1
>> 14/03/26 00:29:48 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
>> 14/03/26 00:29:49 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_1
>> 14/03/26 00:29:49 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:29:49 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=1
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 75%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: SUCCEEDED Progress: 100%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> Vertex Counters for initialmap: Counters: 21
>> File System Counters
>> FILE: BYTES_READ=0
>> FILE: BYTES_WRITTEN=2099
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=1
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=169
>> MAP_OUTPUT_BYTES=1693
>> MAP_OUTPUT_MATERIALIZED_BYTES=2043
>> SPILLED_RECORDS=169
>> GC_TIME_MILLIS=232
>> CPU_MILLISECONDS=-1190
>> PHYSICAL_MEMORY_BYTES=248156160
>> VIRTUAL_MEMORY_BYTES=906416128
>> COMMITTED_HEAP_BYTES=202248192
>> File Input Format Counters
>> Bytes Read=0
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> Vertex Counters for intermediate_reducer: Counters: 32
>> File System Counters
>> FILE: BYTES_READ=2043
>> FILE: BYTES_WRITTEN=3606
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=0
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> MAP_OUTPUT_BYTES=1259
>> MAP_OUTPUT_MATERIALIZED_BYTES=1499
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=114
>> REDUCE_SHUFFLE_BYTES=2043
>> REDUCE_INPUT_RECORDS=169
>> SPILLED_RECORDS=283
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=926
>> CPU_MILLISECONDS=-550
>> PHYSICAL_MEMORY_BYTES=433655808
>> VIRTUAL_MEMORY_BYTES=2449571840
>> COMMITTED_HEAP_BYTES=326901760
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> VertexStatus: VertexName: finalreduce Progress: 100%
>> Vertex Counters for finalreduce: Counters: 31
>> File System Counters
>> FILE: BYTES_READ=1493
>> FILE: BYTES_WRITTEN=1493
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=3
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=6
>> REDUCE_SHUFFLE_BYTES=1499
>> REDUCE_INPUT_RECORDS=114
>> SPILLED_RECORDS=114
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=8
>> CPU_MILLISECONDS=-6720
>> PHYSICAL_MEMORY_BYTES=211603456
>> VIRTUAL_MEMORY_BYTES=1228931072
>> COMMITTED_HEAP_BYTES=163450880
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Output Format Counters
>> Bytes Written=1032
>> DAG Counters: Counters: 36
>> org.apache.tez.common.counters.DAGCounter
>> TOTAL_LAUNCHED_TASKS=4
>> File System Counters
>> FILE: BYTES_READ=3536
>> FILE: BYTES_WRITTEN=7198
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=4
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=397
>> MAP_OUTPUT_BYTES=2952
>> MAP_OUTPUT_MATERIALIZED_BYTES=3542
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=120
>> REDUCE_SHUFFLE_BYTES=3542
>> REDUCE_INPUT_RECORDS=283
>> SPILLED_RECORDS=566
>> SHUFFLED_MAPS=4
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=4
>> GC_TIME_MILLIS=1166
>> CPU_MILLISECONDS=-8460
>> PHYSICAL_MEMORY_BYTES=893415424
>> VIRTUAL_MEMORY_BYTES=4584919040
>> COMMITTED_HEAP_BYTES=692600832
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Input Format Counters
>> Bytes Read=0
>> File Output Format Counters
>> Bytes Written=1032
>> 14/03/26 00:30:19 INFO examples.OrderedWordCount: DAG 1 completed. FinalState=SUCCEEDED
>> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out2
>> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
>> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=2
>> 14/03/26 00:30:19 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
>> 14/03/26 00:30:19 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_2
>> 14/03/26 00:30:19 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=2
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 75%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: SUCCEEDED Progress: 100%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> Vertex Counters for initialmap: Counters: 21
>> File System Counters
>> FILE: BYTES_READ=0
>> FILE: BYTES_WRITTEN=2099
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=1
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=169
>> MAP_OUTPUT_BYTES=1693
>> MAP_OUTPUT_MATERIALIZED_BYTES=2043
>> SPILLED_RECORDS=169
>> GC_TIME_MILLIS=194
>> CPU_MILLISECONDS=-650
>> PHYSICAL_MEMORY_BYTES=263884800
>> VIRTUAL_MEMORY_BYTES=906760192
>> COMMITTED_HEAP_BYTES=202248192
>> File Input Format Counters
>> Bytes Read=0
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> Vertex Counters for intermediate_reducer: Counters: 32
>> File System Counters
>> FILE: BYTES_READ=2043
>> FILE: BYTES_WRITTEN=3606
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=0
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> MAP_OUTPUT_BYTES=1259
>> MAP_OUTPUT_MATERIALIZED_BYTES=1499
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=114
>> REDUCE_SHUFFLE_BYTES=2043
>> REDUCE_INPUT_RECORDS=169
>> SPILLED_RECORDS=283
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=738
>> CPU_MILLISECONDS=-380
>> PHYSICAL_MEMORY_BYTES=453808128
>> VIRTUAL_MEMORY_BYTES=2449682432
>> COMMITTED_HEAP_BYTES=326901760
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> VertexStatus: VertexName: finalreduce Progress: 100%
>> Vertex Counters for finalreduce: Counters: 31
>> File System Counters
>> FILE: BYTES_READ=1493
>> FILE: BYTES_WRITTEN=1493
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=3
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=6
>> REDUCE_SHUFFLE_BYTES=1499
>> REDUCE_INPUT_RECORDS=114
>> SPILLED_RECORDS=114
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=10
>> CPU_MILLISECONDS=-6130
>> PHYSICAL_MEMORY_BYTES=230133760
>> VIRTUAL_MEMORY_BYTES=1229070336
>> COMMITTED_HEAP_BYTES=163450880
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Output Format Counters
>> Bytes Written=1032
>> DAG Counters: Counters: 36
>> org.apache.tez.common.counters.DAGCounter
>> TOTAL_LAUNCHED_TASKS=4
>> File System Counters
>> FILE: BYTES_READ=3536
>> FILE: BYTES_WRITTEN=7198
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=4
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=397
>> MAP_OUTPUT_BYTES=2952
>> MAP_OUTPUT_MATERIALIZED_BYTES=3542
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=120
>> REDUCE_SHUFFLE_BYTES=3542
>> REDUCE_INPUT_RECORDS=283
>> SPILLED_RECORDS=566
>> SHUFFLED_MAPS=4
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=4
>> GC_TIME_MILLIS=942
>> CPU_MILLISECONDS=-7160
>> PHYSICAL_MEMORY_BYTES=947826688
>> VIRTUAL_MEMORY_BYTES=4585512960
>> COMMITTED_HEAP_BYTES=692600832
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Input Format Counters
>> Bytes Read=0
>> File Output Format Counters
>> Bytes Written=1032
>> 14/03/26 00:30:49 INFO examples.OrderedWordCount: DAG 2 completed. FinalState=SUCCEEDED
>> 14/03/26 00:30:49 INFO client.TezSession: Shutting down Tez Session, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
>> [hive@hdpmaster2 ~]$ hdfs dfs -rm -r /tmp/out*
>> 14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash configuration: Deletion interval = 21600000 minutes, Emptier interval = 0 minutes.
>> Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out1' to trash at: hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
>> 14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash configuration: Deletion interval = 21600000 minutes, Emptier interval = 0 minutes.
>> Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out2' to trash at: hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
>> [hive@hdpmaster2 ~]$ hadoop jar /root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh /tmp/out2 /tmp/wrap_ooziedb.sh /tmp/out3
>> 14/03/26 00:31:11 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:31:12 INFO examples.OrderedWordCount: Creating Tez Session
>> 14/03/26 00:31:12 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:31:12 INFO Configuration.deprecation: fs.default.name is deprecated. Instead, use fs.defaultFS
>> 14/03/26 00:31:13 INFO impl.YarnClientImpl: Submitted application application_1395361607432_0044 to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Created Tez Session
>> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out1
>> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
>> 14/03/26 00:31:20 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=1
>> 14/03/26 00:31:20 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
>> 14/03/26 00:31:21 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_1
>> 14/03/26 00:31:21 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:31:21 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=1
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 75%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: SUCCEEDED Progress: 100%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> Vertex Counters for initialmap: Counters: 21
>> File System Counters
>> FILE: BYTES_READ=0
>> FILE: BYTES_WRITTEN=2099
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=1
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=169
>> MAP_OUTPUT_BYTES=1693
>> MAP_OUTPUT_MATERIALIZED_BYTES=2043
>> SPILLED_RECORDS=169
>> GC_TIME_MILLIS=95
>> CPU_MILLISECONDS=-1100
>> PHYSICAL_MEMORY_BYTES=263622656
>> VIRTUAL_MEMORY_BYTES=906416128
>> COMMITTED_HEAP_BYTES=202248192
>> File Input Format Counters
>> Bytes Read=0
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> Vertex Counters for intermediate_reducer: Counters: 32
>> File System Counters
>> FILE: BYTES_READ=2043
>> FILE: BYTES_WRITTEN=3606
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=0
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> MAP_OUTPUT_BYTES=1259
>> MAP_OUTPUT_MATERIALIZED_BYTES=1499
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=114
>> REDUCE_SHUFFLE_BYTES=2043
>> REDUCE_INPUT_RECORDS=169
>> SPILLED_RECORDS=283
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=456
>> CPU_MILLISECONDS=-1050
>> PHYSICAL_MEMORY_BYTES=451112960
>> VIRTUAL_MEMORY_BYTES=2449186816
>> COMMITTED_HEAP_BYTES=326901760
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> VertexStatus: VertexName: finalreduce Progress: 100%
>> Vertex Counters for finalreduce: Counters: 31
>> File System Counters
>> FILE: BYTES_READ=1493
>> FILE: BYTES_WRITTEN=1493
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=3
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=6
>> REDUCE_SHUFFLE_BYTES=1499
>> REDUCE_INPUT_RECORDS=114
>> SPILLED_RECORDS=114
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=6
>> CPU_MILLISECONDS=-5130
>> PHYSICAL_MEMORY_BYTES=227819520
>> VIRTUAL_MEMORY_BYTES=1228775424
>> COMMITTED_HEAP_BYTES=163450880
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Output Format Counters
>> Bytes Written=1032
>> DAG Counters: Counters: 36
>> org.apache.tez.common.counters.DAGCounter
>> TOTAL_LAUNCHED_TASKS=4
>> File System Counters
>> FILE: BYTES_READ=3536
>> FILE: BYTES_WRITTEN=7198
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=4
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=397
>> MAP_OUTPUT_BYTES=2952
>> MAP_OUTPUT_MATERIALIZED_BYTES=3542
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=120
>> REDUCE_SHUFFLE_BYTES=3542
>> REDUCE_INPUT_RECORDS=283
>> SPILLED_RECORDS=566
>> SHUFFLED_MAPS=4
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=4
>> GC_TIME_MILLIS=557
>> CPU_MILLISECONDS=-7280
>> PHYSICAL_MEMORY_BYTES=942555136
>> VIRTUAL_MEMORY_BYTES=4584378368
>> COMMITTED_HEAP_BYTES=692600832
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Input Format Counters
>> Bytes Read=0
>> File Output Format Counters
>> Bytes Written=1032
>> 14/03/26 00:31:45 INFO examples.OrderedWordCount: DAG 1 completed. FinalState=SUCCEEDED
>> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out2
>> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
>> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=2
>> 14/03/26 00:31:45 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
>> 14/03/26 00:31:45 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_2
>> 14/03/26 00:31:45 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=2
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 75%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: SUCCEEDED Progress: 100%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> Vertex Counters for initialmap: Counters: 21
>> File System Counters
>> FILE: BYTES_READ=0
>> FILE: BYTES_WRITTEN=2099
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=1
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=169
>> MAP_OUTPUT_BYTES=1693
>> MAP_OUTPUT_MATERIALIZED_BYTES=2043
>> SPILLED_RECORDS=169
>> GC_TIME_MILLIS=94
>> CPU_MILLISECONDS=-1080
>> PHYSICAL_MEMORY_BYTES=254423040
>> VIRTUAL_MEMORY_BYTES=906416128
>> COMMITTED_HEAP_BYTES=202248192
>> File Input Format Counters
>> Bytes Read=0
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> Vertex Counters for intermediate_reducer: Counters: 32
>> File System Counters
>> FILE: BYTES_READ=2043
>> FILE: BYTES_WRITTEN=3606
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=0
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> MAP_OUTPUT_BYTES=1259
>> MAP_OUTPUT_MATERIALIZED_BYTES=1499
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=114
>> REDUCE_SHUFFLE_BYTES=2043
>> REDUCE_INPUT_RECORDS=169
>> SPILLED_RECORDS=283
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=504
>> CPU_MILLISECONDS=-990
>> PHYSICAL_MEMORY_BYTES=450039808
>> VIRTUAL_MEMORY_BYTES=2449768448
>> COMMITTED_HEAP_BYTES=326901760
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> VertexStatus: VertexName: finalreduce Progress: 100%
>> Vertex Counters for finalreduce: Counters: 31
>> File System Counters
>> FILE: BYTES_READ=1493
>> FILE: BYTES_WRITTEN=1493
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=3
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=6
>> REDUCE_SHUFFLE_BYTES=1499
>> REDUCE_INPUT_RECORDS=114
>> SPILLED_RECORDS=114
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=6
>> CPU_MILLISECONDS=-5170
>> PHYSICAL_MEMORY_BYTES=229675008
>> VIRTUAL_MEMORY_BYTES=1228996608
>> COMMITTED_HEAP_BYTES=163450880
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Output Format Counters
>> Bytes Written=1032
>> DAG Counters: Counters: 36
>> org.apache.tez.common.counters.DAGCounter
>> TOTAL_LAUNCHED_TASKS=4
>> File System Counters
>> FILE: BYTES_READ=3536
>> FILE: BYTES_WRITTEN=7198
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=4
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=397
>> MAP_OUTPUT_BYTES=2952
>> MAP_OUTPUT_MATERIALIZED_BYTES=3542
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=120
>> REDUCE_SHUFFLE_BYTES=3542
>> REDUCE_INPUT_RECORDS=283
>> SPILLED_RECORDS=566
>> SHUFFLED_MAPS=4
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=4
>> GC_TIME_MILLIS=604
>> CPU_MILLISECONDS=-7240
>> PHYSICAL_MEMORY_BYTES=934137856
>> VIRTUAL_MEMORY_BYTES=4585181184
>> COMMITTED_HEAP_BYTES=692600832
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Input Format Counters
>> Bytes Read=0
>> File Output Format Counters
>> Bytes Written=1032
>> 14/03/26 00:32:11 INFO examples.OrderedWordCount: DAG 2 completed. FinalState=SUCCEEDED
>> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=3, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out3
>> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
>> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=3
>> 14/03/26 00:32:11 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
>> 14/03/26 00:32:11 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_3
>> 14/03/26 00:32:11 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
>> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=3
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 0%
>> VertexStatus: VertexName: initialmap Progress: 0%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 25%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 0%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 50%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 50%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: RUNNING Progress: 75%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> VertexStatus: VertexName: finalreduce Progress: 0%
>>
>> DAG: State: SUCCEEDED Progress: 100%
>> VertexStatus: VertexName: initialmap Progress: 100%
>> Vertex Counters for initialmap: Counters: 21
>> File System Counters
>> FILE: BYTES_READ=0
>> FILE: BYTES_WRITTEN=2099
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=1
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=169
>> MAP_OUTPUT_BYTES=1693
>> MAP_OUTPUT_MATERIALIZED_BYTES=2043
>> SPILLED_RECORDS=169
>> GC_TIME_MILLIS=105
>> CPU_MILLISECONDS=-1030
>> PHYSICAL_MEMORY_BYTES=266383360
>> VIRTUAL_MEMORY_BYTES=906416128
>> COMMITTED_HEAP_BYTES=202248192
>> File Input Format Counters
>> Bytes Read=0
>> VertexStatus: VertexName: intermediate_reducer Progress: 100%
>> Vertex Counters for intermediate_reducer: Counters: 32
>> File System Counters
>> FILE: BYTES_READ=2043
>> FILE: BYTES_WRITTEN=3606
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=0
>> HDFS: READ_OPS=0
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=0
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> MAP_OUTPUT_BYTES=1259
>> MAP_OUTPUT_MATERIALIZED_BYTES=1499
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=114
>> REDUCE_SHUFFLE_BYTES=2043
>> REDUCE_INPUT_RECORDS=169
>> SPILLED_RECORDS=283
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=385
>> CPU_MILLISECONDS=-1090
>> PHYSICAL_MEMORY_BYTES=432283648
>> VIRTUAL_MEMORY_BYTES=2449825792
>> COMMITTED_HEAP_BYTES=326901760
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> VertexStatus: VertexName: finalreduce Progress: 100%
>> Vertex Counters for finalreduce: Counters: 31
>> File System Counters
>> FILE: BYTES_READ=1493
>> FILE: BYTES_WRITTEN=1493
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=0
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=3
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_OUTPUT_RECORDS=114
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=6
>> REDUCE_SHUFFLE_BYTES=1499
>> REDUCE_INPUT_RECORDS=114
>> SPILLED_RECORDS=114
>> SHUFFLED_MAPS=2
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=2
>> GC_TIME_MILLIS=6
>> CPU_MILLISECONDS=-5240
>> PHYSICAL_MEMORY_BYTES=225894400
>> VIRTUAL_MEMORY_BYTES=1228943360
>> COMMITTED_HEAP_BYTES=163450880
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Output Format Counters
>> Bytes Written=1032
>> DAG Counters: Counters: 36
>> org.apache.tez.common.counters.DAGCounter
>> TOTAL_LAUNCHED_TASKS=4
>> File System Counters
>> FILE: BYTES_READ=3536
>> FILE: BYTES_WRITTEN=7198
>> FILE: READ_OPS=0
>> FILE: LARGE_READ_OPS=0
>> FILE: WRITE_OPS=0
>> HDFS: BYTES_READ=1029
>> HDFS: BYTES_WRITTEN=1032
>> HDFS: READ_OPS=4
>> HDFS: LARGE_READ_OPS=0
>> HDFS: WRITE_OPS=2
>> org.apache.tez.common.counters.TaskCounter
>> MAP_INPUT_RECORDS=31
>> MAP_OUTPUT_RECORDS=397
>> MAP_OUTPUT_BYTES=2952
>> MAP_OUTPUT_MATERIALIZED_BYTES=3542
>> COMBINE_INPUT_RECORDS=0
>> REDUCE_INPUT_GROUPS=120
>> REDUCE_SHUFFLE_BYTES=3542
>> REDUCE_INPUT_RECORDS=283
>> SPILLED_RECORDS=566
>> SHUFFLED_MAPS=4
>> FAILED_SHUFFLE=0
>> MERGED_MAP_OUTPUTS=4
>> GC_TIME_MILLIS=496
>> CPU_MILLISECONDS=-7360
>> PHYSICAL_MEMORY_BYTES=924561408
>> VIRTUAL_MEMORY_BYTES=4585185280
>> COMMITTED_HEAP_BYTES=692600832
>> Shuffle Errors
>> BAD_ID=0
>> CONNECTION=0
>> IO_ERROR=0
>> WRONG_LENGTH=0
>> WRONG_MAP=0
>> WRONG_REDUCE=0
>> File Input Format Counters
>> Bytes Read=0
>> File Output Format Counters
>> Bytes Written=1032
>> 14/03/26 00:32:36 INFO examples.OrderedWordCount: DAG 3 completed. FinalState=SUCCEEDED
>> 14/03/26 00:32:37 INFO client.TezSession: Shutting down Tez Session, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
>> [hive@hdpmaster2 ~]$
>>
Re: No seeing tez based speedup
Posted by Hitesh Shah <hi...@apache.org>.
Hello Amit,
Some initial questions:
- are you running this on a single node?
- if yes, what are the settings in mapred-site for the following:
- mapreduce.map.memory.mb, mapreduce.reduce.memory.mb
- mapreduce.map.java.opts, mapreduce.reduce.java.opts
The reason the above may affect your job is how containers are re-used. If the map and reduce settings are different, containers may not get re-used and if your cluster is not big enough, it may end up releasing containers to get containers for the next stage. This will reduce the perf benefits of re-using the containers used by the previous DAG.
Also, could you provide a copy of your tez-site.xml? And, if possible, try the same run again but with tez.am.log.level set to DEBUG in tez-site.xml
thanks
-- Hitesh
On Mar 25, 2014, at 5:56 PM, Amit Tewari wrote:
> I tried to run orderedwordcount example with 3 inputs and outputs expecting to see speed up in second and third DAG execution. However I found all the executions took roughly the same amount of time. Its more concerning that I used the same input for every iteration.
>
> Full log is included below.
>
> Not sure where to start debugging this. Any pointers ?
>
>
> -A
>
>
> [hive@hdpmaster2 ~]$hadoop jar /root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh /tmp/out2
> 14/03/26 00:29:40 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:29:41 INFO examples.OrderedWordCount: Creating Tez Session
> 14/03/26 00:29:41 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:29:41 INFO Configuration.deprecation: fs.default.name is deprecated. Instead, use fs.defaultFS
> 14/03/26 00:29:42 INFO impl.YarnClientImpl: Submitted application application_1395361607432_0043 to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Created Tez Session
> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out1
> 14/03/26 00:29:42 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
> 14/03/26 00:29:48 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=1
> 14/03/26 00:29:48 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
> 14/03/26 00:29:49 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_1
> 14/03/26 00:29:49 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:29:49 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=1
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 75%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: SUCCEEDED Progress: 100%
> VertexStatus: VertexName: initialmap Progress: 100%
> Vertex Counters for initialmap: Counters: 21
> File System Counters
> FILE: BYTES_READ=0
> FILE: BYTES_WRITTEN=2099
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=1
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=169
> MAP_OUTPUT_BYTES=1693
> MAP_OUTPUT_MATERIALIZED_BYTES=2043
> SPILLED_RECORDS=169
> GC_TIME_MILLIS=232
> CPU_MILLISECONDS=-1190
> PHYSICAL_MEMORY_BYTES=248156160
> VIRTUAL_MEMORY_BYTES=906416128
> COMMITTED_HEAP_BYTES=202248192
> File Input Format Counters
> Bytes Read=0
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> Vertex Counters for intermediate_reducer: Counters: 32
> File System Counters
> FILE: BYTES_READ=2043
> FILE: BYTES_WRITTEN=3606
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=0
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> MAP_OUTPUT_BYTES=1259
> MAP_OUTPUT_MATERIALIZED_BYTES=1499
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=114
> REDUCE_SHUFFLE_BYTES=2043
> REDUCE_INPUT_RECORDS=169
> SPILLED_RECORDS=283
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=926
> CPU_MILLISECONDS=-550
> PHYSICAL_MEMORY_BYTES=433655808
> VIRTUAL_MEMORY_BYTES=2449571840
> COMMITTED_HEAP_BYTES=326901760
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> VertexStatus: VertexName: finalreduce Progress: 100%
> Vertex Counters for finalreduce: Counters: 31
> File System Counters
> FILE: BYTES_READ=1493
> FILE: BYTES_WRITTEN=1493
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=3
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=6
> REDUCE_SHUFFLE_BYTES=1499
> REDUCE_INPUT_RECORDS=114
> SPILLED_RECORDS=114
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=8
> CPU_MILLISECONDS=-6720
> PHYSICAL_MEMORY_BYTES=211603456
> VIRTUAL_MEMORY_BYTES=1228931072
> COMMITTED_HEAP_BYTES=163450880
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Output Format Counters
> Bytes Written=1032
> DAG Counters: Counters: 36
> org.apache.tez.common.counters.DAGCounter
> TOTAL_LAUNCHED_TASKS=4
> File System Counters
> FILE: BYTES_READ=3536
> FILE: BYTES_WRITTEN=7198
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=4
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=397
> MAP_OUTPUT_BYTES=2952
> MAP_OUTPUT_MATERIALIZED_BYTES=3542
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=120
> REDUCE_SHUFFLE_BYTES=3542
> REDUCE_INPUT_RECORDS=283
> SPILLED_RECORDS=566
> SHUFFLED_MAPS=4
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=4
> GC_TIME_MILLIS=1166
> CPU_MILLISECONDS=-8460
> PHYSICAL_MEMORY_BYTES=893415424
> VIRTUAL_MEMORY_BYTES=4584919040
> COMMITTED_HEAP_BYTES=692600832
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=0
> File Output Format Counters
> Bytes Written=1032
> 14/03/26 00:30:19 INFO examples.OrderedWordCount: DAG 1 completed. FinalState=SUCCEEDED
> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out2
> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=2
> 14/03/26 00:30:19 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
> 14/03/26 00:30:19 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043, dagId=dag_1395361607432_0043_2
> 14/03/26 00:30:19 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:30:19 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=2
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 75%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: SUCCEEDED Progress: 100%
> VertexStatus: VertexName: initialmap Progress: 100%
> Vertex Counters for initialmap: Counters: 21
> File System Counters
> FILE: BYTES_READ=0
> FILE: BYTES_WRITTEN=2099
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=1
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=169
> MAP_OUTPUT_BYTES=1693
> MAP_OUTPUT_MATERIALIZED_BYTES=2043
> SPILLED_RECORDS=169
> GC_TIME_MILLIS=194
> CPU_MILLISECONDS=-650
> PHYSICAL_MEMORY_BYTES=263884800
> VIRTUAL_MEMORY_BYTES=906760192
> COMMITTED_HEAP_BYTES=202248192
> File Input Format Counters
> Bytes Read=0
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> Vertex Counters for intermediate_reducer: Counters: 32
> File System Counters
> FILE: BYTES_READ=2043
> FILE: BYTES_WRITTEN=3606
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=0
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> MAP_OUTPUT_BYTES=1259
> MAP_OUTPUT_MATERIALIZED_BYTES=1499
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=114
> REDUCE_SHUFFLE_BYTES=2043
> REDUCE_INPUT_RECORDS=169
> SPILLED_RECORDS=283
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=738
> CPU_MILLISECONDS=-380
> PHYSICAL_MEMORY_BYTES=453808128
> VIRTUAL_MEMORY_BYTES=2449682432
> COMMITTED_HEAP_BYTES=326901760
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> VertexStatus: VertexName: finalreduce Progress: 100%
> Vertex Counters for finalreduce: Counters: 31
> File System Counters
> FILE: BYTES_READ=1493
> FILE: BYTES_WRITTEN=1493
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=3
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=6
> REDUCE_SHUFFLE_BYTES=1499
> REDUCE_INPUT_RECORDS=114
> SPILLED_RECORDS=114
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=10
> CPU_MILLISECONDS=-6130
> PHYSICAL_MEMORY_BYTES=230133760
> VIRTUAL_MEMORY_BYTES=1229070336
> COMMITTED_HEAP_BYTES=163450880
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Output Format Counters
> Bytes Written=1032
> DAG Counters: Counters: 36
> org.apache.tez.common.counters.DAGCounter
> TOTAL_LAUNCHED_TASKS=4
> File System Counters
> FILE: BYTES_READ=3536
> FILE: BYTES_WRITTEN=7198
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=4
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=397
> MAP_OUTPUT_BYTES=2952
> MAP_OUTPUT_MATERIALIZED_BYTES=3542
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=120
> REDUCE_SHUFFLE_BYTES=3542
> REDUCE_INPUT_RECORDS=283
> SPILLED_RECORDS=566
> SHUFFLED_MAPS=4
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=4
> GC_TIME_MILLIS=942
> CPU_MILLISECONDS=-7160
> PHYSICAL_MEMORY_BYTES=947826688
> VIRTUAL_MEMORY_BYTES=4585512960
> COMMITTED_HEAP_BYTES=692600832
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=0
> File Output Format Counters
> Bytes Written=1032
> 14/03/26 00:30:49 INFO examples.OrderedWordCount: DAG 2 completed. FinalState=SUCCEEDED
> 14/03/26 00:30:49 INFO client.TezSession: Shutting down Tez Session, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0043
> [hive@hdpmaster2 ~]$ hdfs dfs -rm -r /tmp/out*
> 14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash configuration: Deletion interval = 21600000 minutes, Emptier interval = 0 minutes.
> Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out1' to trash at: hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
> 14/03/26 00:30:58 INFO fs.TrashPolicyDefault: Namenode trash configuration: Deletion interval = 21600000 minutes, Emptier interval = 0 minutes.
> Moved: 'hdfs://hdpmaster1.hdp.hadoop:8020/tmp/out2' to trash at: hdfs://hdpmaster1.hdp.hadoop:8020/user/hive/.Trash/Current
> [hive@hdpmaster2 ~]$ hadoop jar /root/tez-0.3.0/tez-mapreduce-examples/target/tez-mapreduce-examples-0.3.0-incubating.jar orderedwordcount /tmp/wrap_ooziedb.sh /tmp/out1 /tmp/wrap_ooziedb.sh /tmp/out2 /tmp/wrap_ooziedb.sh /tmp/out3
> 14/03/26 00:31:11 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:31:12 INFO examples.OrderedWordCount: Creating Tez Session
> 14/03/26 00:31:12 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:31:12 INFO Configuration.deprecation: fs.default.name is deprecated. Instead, use fs.defaultFS
> 14/03/26 00:31:13 INFO impl.YarnClientImpl: Submitted application application_1395361607432_0044 to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Created Tez Session
> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=1, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out1
> 14/03/26 00:31:13 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
> 14/03/26 00:31:20 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=1
> 14/03/26 00:31:20 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
> 14/03/26 00:31:21 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_1
> 14/03/26 00:31:21 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:31:21 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=1
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 75%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: SUCCEEDED Progress: 100%
> VertexStatus: VertexName: initialmap Progress: 100%
> Vertex Counters for initialmap: Counters: 21
> File System Counters
> FILE: BYTES_READ=0
> FILE: BYTES_WRITTEN=2099
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=1
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=169
> MAP_OUTPUT_BYTES=1693
> MAP_OUTPUT_MATERIALIZED_BYTES=2043
> SPILLED_RECORDS=169
> GC_TIME_MILLIS=95
> CPU_MILLISECONDS=-1100
> PHYSICAL_MEMORY_BYTES=263622656
> VIRTUAL_MEMORY_BYTES=906416128
> COMMITTED_HEAP_BYTES=202248192
> File Input Format Counters
> Bytes Read=0
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> Vertex Counters for intermediate_reducer: Counters: 32
> File System Counters
> FILE: BYTES_READ=2043
> FILE: BYTES_WRITTEN=3606
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=0
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> MAP_OUTPUT_BYTES=1259
> MAP_OUTPUT_MATERIALIZED_BYTES=1499
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=114
> REDUCE_SHUFFLE_BYTES=2043
> REDUCE_INPUT_RECORDS=169
> SPILLED_RECORDS=283
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=456
> CPU_MILLISECONDS=-1050
> PHYSICAL_MEMORY_BYTES=451112960
> VIRTUAL_MEMORY_BYTES=2449186816
> COMMITTED_HEAP_BYTES=326901760
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> VertexStatus: VertexName: finalreduce Progress: 100%
> Vertex Counters for finalreduce: Counters: 31
> File System Counters
> FILE: BYTES_READ=1493
> FILE: BYTES_WRITTEN=1493
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=3
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=6
> REDUCE_SHUFFLE_BYTES=1499
> REDUCE_INPUT_RECORDS=114
> SPILLED_RECORDS=114
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=6
> CPU_MILLISECONDS=-5130
> PHYSICAL_MEMORY_BYTES=227819520
> VIRTUAL_MEMORY_BYTES=1228775424
> COMMITTED_HEAP_BYTES=163450880
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Output Format Counters
> Bytes Written=1032
> DAG Counters: Counters: 36
> org.apache.tez.common.counters.DAGCounter
> TOTAL_LAUNCHED_TASKS=4
> File System Counters
> FILE: BYTES_READ=3536
> FILE: BYTES_WRITTEN=7198
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=4
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=397
> MAP_OUTPUT_BYTES=2952
> MAP_OUTPUT_MATERIALIZED_BYTES=3542
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=120
> REDUCE_SHUFFLE_BYTES=3542
> REDUCE_INPUT_RECORDS=283
> SPILLED_RECORDS=566
> SHUFFLED_MAPS=4
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=4
> GC_TIME_MILLIS=557
> CPU_MILLISECONDS=-7280
> PHYSICAL_MEMORY_BYTES=942555136
> VIRTUAL_MEMORY_BYTES=4584378368
> COMMITTED_HEAP_BYTES=692600832
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=0
> File Output Format Counters
> Bytes Written=1032
> 14/03/26 00:31:45 INFO examples.OrderedWordCount: DAG 1 completed. FinalState=SUCCEEDED
> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=2, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out2
> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=2
> 14/03/26 00:31:45 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
> 14/03/26 00:31:45 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_2
> 14/03/26 00:31:45 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:31:45 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=2
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 75%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: SUCCEEDED Progress: 100%
> VertexStatus: VertexName: initialmap Progress: 100%
> Vertex Counters for initialmap: Counters: 21
> File System Counters
> FILE: BYTES_READ=0
> FILE: BYTES_WRITTEN=2099
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=1
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=169
> MAP_OUTPUT_BYTES=1693
> MAP_OUTPUT_MATERIALIZED_BYTES=2043
> SPILLED_RECORDS=169
> GC_TIME_MILLIS=94
> CPU_MILLISECONDS=-1080
> PHYSICAL_MEMORY_BYTES=254423040
> VIRTUAL_MEMORY_BYTES=906416128
> COMMITTED_HEAP_BYTES=202248192
> File Input Format Counters
> Bytes Read=0
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> Vertex Counters for intermediate_reducer: Counters: 32
> File System Counters
> FILE: BYTES_READ=2043
> FILE: BYTES_WRITTEN=3606
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=0
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> MAP_OUTPUT_BYTES=1259
> MAP_OUTPUT_MATERIALIZED_BYTES=1499
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=114
> REDUCE_SHUFFLE_BYTES=2043
> REDUCE_INPUT_RECORDS=169
> SPILLED_RECORDS=283
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=504
> CPU_MILLISECONDS=-990
> PHYSICAL_MEMORY_BYTES=450039808
> VIRTUAL_MEMORY_BYTES=2449768448
> COMMITTED_HEAP_BYTES=326901760
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> VertexStatus: VertexName: finalreduce Progress: 100%
> Vertex Counters for finalreduce: Counters: 31
> File System Counters
> FILE: BYTES_READ=1493
> FILE: BYTES_WRITTEN=1493
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=3
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=6
> REDUCE_SHUFFLE_BYTES=1499
> REDUCE_INPUT_RECORDS=114
> SPILLED_RECORDS=114
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=6
> CPU_MILLISECONDS=-5170
> PHYSICAL_MEMORY_BYTES=229675008
> VIRTUAL_MEMORY_BYTES=1228996608
> COMMITTED_HEAP_BYTES=163450880
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Output Format Counters
> Bytes Written=1032
> DAG Counters: Counters: 36
> org.apache.tez.common.counters.DAGCounter
> TOTAL_LAUNCHED_TASKS=4
> File System Counters
> FILE: BYTES_READ=3536
> FILE: BYTES_WRITTEN=7198
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=4
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=397
> MAP_OUTPUT_BYTES=2952
> MAP_OUTPUT_MATERIALIZED_BYTES=3542
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=120
> REDUCE_SHUFFLE_BYTES=3542
> REDUCE_INPUT_RECORDS=283
> SPILLED_RECORDS=566
> SHUFFLED_MAPS=4
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=4
> GC_TIME_MILLIS=604
> CPU_MILLISECONDS=-7240
> PHYSICAL_MEMORY_BYTES=934137856
> VIRTUAL_MEMORY_BYTES=4585181184
> COMMITTED_HEAP_BYTES=692600832
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=0
> File Output Format Counters
> Bytes Written=1032
> 14/03/26 00:32:11 INFO examples.OrderedWordCount: DAG 2 completed. FinalState=SUCCEEDED
> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Running OrderedWordCount DAG, dagIndex=3, inputPath=/tmp/wrap_ooziedb.sh, outputPath=/tmp/out3
> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Waiting for TezSession to get into ready state
> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitting DAG to Tez Session, dagIndex=3
> 14/03/26 00:32:11 INFO client.TezSession: Submitting dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
> 14/03/26 00:32:11 INFO client.TezSession: Submitted dag to TezSession, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044, dagId=dag_1395361607432_0044_3
> 14/03/26 00:32:11 INFO client.RMProxy: Connecting to ResourceManager at hdpmaster2.hdp.hadoop/10.178.26.162:8050
> 14/03/26 00:32:11 INFO examples.OrderedWordCount: Submitted DAG to Tez Session, dagIndex=3
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 0%
> VertexStatus: VertexName: initialmap Progress: 0%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 25%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 0%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 50%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 50%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: RUNNING Progress: 75%
> VertexStatus: VertexName: initialmap Progress: 100%
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> VertexStatus: VertexName: finalreduce Progress: 0%
>
> DAG: State: SUCCEEDED Progress: 100%
> VertexStatus: VertexName: initialmap Progress: 100%
> Vertex Counters for initialmap: Counters: 21
> File System Counters
> FILE: BYTES_READ=0
> FILE: BYTES_WRITTEN=2099
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=1
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=169
> MAP_OUTPUT_BYTES=1693
> MAP_OUTPUT_MATERIALIZED_BYTES=2043
> SPILLED_RECORDS=169
> GC_TIME_MILLIS=105
> CPU_MILLISECONDS=-1030
> PHYSICAL_MEMORY_BYTES=266383360
> VIRTUAL_MEMORY_BYTES=906416128
> COMMITTED_HEAP_BYTES=202248192
> File Input Format Counters
> Bytes Read=0
> VertexStatus: VertexName: intermediate_reducer Progress: 100%
> Vertex Counters for intermediate_reducer: Counters: 32
> File System Counters
> FILE: BYTES_READ=2043
> FILE: BYTES_WRITTEN=3606
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=0
> HDFS: READ_OPS=0
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=0
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> MAP_OUTPUT_BYTES=1259
> MAP_OUTPUT_MATERIALIZED_BYTES=1499
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=114
> REDUCE_SHUFFLE_BYTES=2043
> REDUCE_INPUT_RECORDS=169
> SPILLED_RECORDS=283
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=385
> CPU_MILLISECONDS=-1090
> PHYSICAL_MEMORY_BYTES=432283648
> VIRTUAL_MEMORY_BYTES=2449825792
> COMMITTED_HEAP_BYTES=326901760
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> VertexStatus: VertexName: finalreduce Progress: 100%
> Vertex Counters for finalreduce: Counters: 31
> File System Counters
> FILE: BYTES_READ=1493
> FILE: BYTES_WRITTEN=1493
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=0
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=3
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_OUTPUT_RECORDS=114
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=6
> REDUCE_SHUFFLE_BYTES=1499
> REDUCE_INPUT_RECORDS=114
> SPILLED_RECORDS=114
> SHUFFLED_MAPS=2
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=2
> GC_TIME_MILLIS=6
> CPU_MILLISECONDS=-5240
> PHYSICAL_MEMORY_BYTES=225894400
> VIRTUAL_MEMORY_BYTES=1228943360
> COMMITTED_HEAP_BYTES=163450880
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Output Format Counters
> Bytes Written=1032
> DAG Counters: Counters: 36
> org.apache.tez.common.counters.DAGCounter
> TOTAL_LAUNCHED_TASKS=4
> File System Counters
> FILE: BYTES_READ=3536
> FILE: BYTES_WRITTEN=7198
> FILE: READ_OPS=0
> FILE: LARGE_READ_OPS=0
> FILE: WRITE_OPS=0
> HDFS: BYTES_READ=1029
> HDFS: BYTES_WRITTEN=1032
> HDFS: READ_OPS=4
> HDFS: LARGE_READ_OPS=0
> HDFS: WRITE_OPS=2
> org.apache.tez.common.counters.TaskCounter
> MAP_INPUT_RECORDS=31
> MAP_OUTPUT_RECORDS=397
> MAP_OUTPUT_BYTES=2952
> MAP_OUTPUT_MATERIALIZED_BYTES=3542
> COMBINE_INPUT_RECORDS=0
> REDUCE_INPUT_GROUPS=120
> REDUCE_SHUFFLE_BYTES=3542
> REDUCE_INPUT_RECORDS=283
> SPILLED_RECORDS=566
> SHUFFLED_MAPS=4
> FAILED_SHUFFLE=0
> MERGED_MAP_OUTPUTS=4
> GC_TIME_MILLIS=496
> CPU_MILLISECONDS=-7360
> PHYSICAL_MEMORY_BYTES=924561408
> VIRTUAL_MEMORY_BYTES=4585185280
> COMMITTED_HEAP_BYTES=692600832
> Shuffle Errors
> BAD_ID=0
> CONNECTION=0
> IO_ERROR=0
> WRONG_LENGTH=0
> WRONG_MAP=0
> WRONG_REDUCE=0
> File Input Format Counters
> Bytes Read=0
> File Output Format Counters
> Bytes Written=1032
> 14/03/26 00:32:36 INFO examples.OrderedWordCount: DAG 3 completed. FinalState=SUCCEEDED
> 14/03/26 00:32:37 INFO client.TezSession: Shutting down Tez Session, sessionName=OrderedWordCountSession, applicationId=application_1395361607432_0044
> [hive@hdpmaster2 ~]$
>