[TEZ-1118] Tez with container reuse reports negative CPU usage

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.4.0, 0.5.0
• Fix Version/s: 0.5.0
• Labels: cpu-counters tez-counters
• Target Version/s: 0.4.0, 0.5.0
• Assignee: Gopal Vijayaraghavan
• Reporter: Sergey Shelukhin
• Created: 13/May/14 22:52
• Updated: 06/Sep/14 01:35
• Resolved: 09/Jul/14 03:10

Description

2014-05-13 12:47:37,243 INFO [AsyncDispatcher event handler] org.apache.tez.dag.history.HistoryEventHandler: [HISTORY][DAG:dag_1399351577718_0764_8][Event:TASK_ATTEMPT_FINISHED]: vertexName=Map 2, taskAttemptId=attempt_1399351577718_0764_8_01_000321_0, startTime=1400010446382, finishTime=1400010457242, timeTaken=10860, status=SUCCEEDED, diagnostics=, counters=Counters: 30, org.apache.tez.common.counters.DAGCounter, RACK_LOCAL_TASKS=1, File System Counters, FILE: BYTES_READ=32, FILE: BYTES_WRITTEN=103495, FILE: READ_OPS=0, FILE: LARGE_READ_OPS=0, FILE: WRITE_OPS=0, HDFS: BYTES_READ=158991064, HDFS: BYTES_WRITTEN=0, HDFS: READ_OPS=2, HDFS: LARGE_READ_OPS=0, HDFS: WRITE_OPS=0, org.apache.tez.common.counters.TaskCounter, GC_TIME_MILLIS=72, CPU_MILLISECONDS=-455600

This seems to get worse as new tasks are scheduled on the container, CPU is obvious column in this csv (attempts are in execution order):

Map 2,attempt_1399351577718_0764_1_01_000063_0,22678,269235481,27830,17536,11967
Map 2,attempt_1399351577718_0764_1_01_000167_0,16472,265337919,-19970,17044,11854
Map 2,attempt_1399351577718_0764_1_01_000301_0,10197,173878898,-46140,11427,6899
Map 2,attempt_1399351577718_0764_2_01_000059_0,18545,269736723,-51050,17590,12271
Map 2,attempt_1399351577718_0764_2_01_000107_0,14677,269520373,-84270,17673,11095
Map 2,attempt_1399351577718_0764_2_01_000228_0,14910,261276556,-104380,16937,11470
Map 2,attempt_1399351577718_0764_3_01_000008_0,16164,269641107,-124260,17013,11306
Map 2,attempt_1399351577718_0764_3_01_000136_0,15105,267827690,-140730,17834,10370
Map 2,attempt_1399351577718_0764_3_01_000240_0,17380,235117784,-165260,15303,10948
Map 2,attempt_1399351577718_0764_4_01_000056_0,19848,269790867,-167870,17487,11510
Map 2,attempt_1399351577718_0764_4_01_000146_0,15303,267603313,-204130,17029,11672
Map 2,attempt_1399351577718_0764_4_01_000264_0,9518,188372846,-231590,12273,8495
Map 2,attempt_1399351577718_0764_5_01_000024_0,15836,270431273,-229970,17688,11045
Map 2,attempt_1399351577718_0764_5_01_000150_0,15368,266500919,-258690,17012,11385
Map 2,attempt_1399351577718_0764_5_01_000266_0,11882,183276660,-286700,11893,8350
Map 2,attempt_1399351577718_0764_6_01_000017_0,17037,270252275,-293420,17517,12030
Map 2,attempt_1399351577718_0764_6_01_000156_0,12759,266500919,-313380,17012,11385
Map 2,attempt_1399351577718_0764_6_01_000266_0,10078,188372846,-338580,12273,8495
Map 2,attempt_1399351577718_0764_7_01_000021_0,15984,270757527,-343980,17972,11519
Map 2,attempt_1399351577718_0764_7_01_000102_0,14149,269589224,-355560,17698,10871
Map 2,attempt_1399351577718_0764_7_01_000243_0,11578,235644691,-395730,15244,10508
Map 2,attempt_1399351577718_0764_8_01_000026_0,16377,270431273,-402260,17688,11045
Map 2,attempt_1399351577718_0764_8_01_000127_0,15517,268903941,-422380,17591,11681
Map 2,attempt_1399351577718_0764_8_01_000321_0,10860,158991064,-455600,10658,6764