improving the logging during shuffling

• Key: HADOOP-3332
• Type: Improvement
• Status: Closed
• Resolution: Fixed
• Priority: Blocker
• Assignee: Devaraj Das
• Reporter: Runping Qi
• Affects Version/s: 0.18.0
• Fix Version/s: 0.18.0

Description

Below is an excerpt from the log file of a reducer.
A same set of of messages about fetching schedule is logged every second.
Yet, the critical information — which hosts were slow — was not there.

2008-05-01 00:33:13,215 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Need another 3 map output(s) where 1 is already in progress
2008-05-01 00:33:14,216 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0: Got 0 new map-outputs & 0 obsolete map-outputs from tasktracker and 0 map-outputs from previous failures
2008-05-01 00:33:14,216 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Got 2 known map output location(s); scheduling...
2008-05-01 00:33:14,216 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Scheduled 0 of 2 known outputs (2 slow hosts and 0 dup hosts)
2008-05-01 00:33:14,216 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Need another 3 map output(s) where 1 is already in progress
2008-05-01 00:33:15,217 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0: Got 0 new map-outputs & 0 obsolete map-outputs from tasktracker and 0 map-outputs from previous failures
2008-05-01 00:33:15,217 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Got 2 known map output location(s); scheduling...
2008-05-01 00:33:15,217 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Scheduled 0 of 2 known outputs (2 slow hosts and 0 dup hosts)
2008-05-01 00:33:15,217 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0 Need another 3 map output(s) where 1 is already in progress
2008-05-01 00:33:16,218 INFO org.apache.hadoop.mapred.ReduceTask: task_200804302255_0002_r_000720_0: Got 0 new map-outputs & 0 obsolete map-outputs from tasktracker and 0 map-outputs from previous failures

Comments

[Runping Qi]

It turns out that this problem is much more severe that it looks initially.
For any reasonable size of jobs where the shuffling may take some time, the userlog/syslog file of each reducer task may
reach unreasonably large (0.5GB, say). This may impose a big burden for hod to harvest the log files when deallocating
a cluster. Also, if those log files are archived on a DFS (as what the hod does now), the space requirements on DFS
will be quite significant.

[Arun C Murthy]

It turns out that this problem is much more severe that it looks initially. [...]

+1, I've seen this happen too. THe hod log-harvester was eating up CPU on each of the task-trackers...

[Devaraj Das]

Straightforward patch..

[Runping Qi]

Does this patch address the issue of excessive logging (resulting in hudge log files)?

[Devaraj Das]

sigh I forgot about that point. Will upload one shortly.

[Devaraj Das]

Here is another stab at this. The patch logs only when updates happen or a specific time limit expires (1 minute). I hope I have covered all possible logging that happens frequently in the shuffle.

[Runping Qi]

Does this patch apply to 0.17?
I don't think we can deploy 0.17 without cutting down the logging volume.

[Hadoop QA]

-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12381688/3332.patch
against trunk revision 654315.

+1 @author. The patch does not contain any @author tags.

-1 tests included. The patch doesn't appear to include any new or modified tests.
Please justify why no tests are needed for this patch.

+1 javadoc. The javadoc tool did not generate any warning messages.

+1 javac. The applied patch does not increase the total number of javac compiler warnings.

+1 findbugs. The patch does not introduce any new Findbugs warnings.

+1 release audit. The applied patch does not increase the total number of release audit warnings.

+1 core tests. The patch passed core unit tests.

+1 contrib tests. The patch passed contrib unit tests.

Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2430/testReport/
Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2430/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2430/artifact/trunk/build/test/checkstyle-errors.html
Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2430/console

This message is automatically generated.

[Devaraj Das]

No this patch doesn't apply to 0.17. I will put up a version for 0.17

[Devaraj Das]

This patch is for the 0.17 branch

[Runping Qi]

The patch looks good.

It should be checked into 17 too.
Without this fix, the log file of EACH reduce task can easily reach gig bytes in size; any useful information
will be burried in the huge volume of repeated noise, thus will be hard to find. Log archiving will also be problematic.

[Arun C Murthy]

I'm a little concerned about doing adding a 'gettimeofday'-ish call in the inner-loop; especially when it is just for logging...

[Devaraj Das]

Arun, actually there was a call to currentTimeMillis already. I moved it up so that it can be reused for logging also. From the patch, this is the place where currentTime is removed from...

@@ -1098,7 +1123,7 @@

Iterator<MapOutputLocation> locIt = knownOutputs.iterator();

• currentTime = System.currentTimeMillis();
  +
  while (locIt.hasNext()) {

MapOutputLocation loc = locIt.next();
@@ -1112,8 +1137,12 @@

[Arun C Murthy]

I might be missing something, but the patch moves it down into the while loop, from outside it...

Can we do something simple like log every 1% of shuffle progress or something like that? i.e. log status once we copy 1% of map-outputs...

[Devaraj Das]

Hey Arun, if you see the fetchOutputs method, the entire stuff is within a big while loop "while (!neededOutputs.isEmpty() && mergeThrowable == null) {" The call to System.currentTimeMillis was within that earlier (to be precise within, synchronized (scheduledCopies) ), I moved it outside the "synchronized (scheduledCopies)" and I think I moved it to the place where it should be in the loop.

[Amar Kamat]

.... actually there was a call to currentTimeMillis already. I moved it up so that it can be reused for logging also. ....

+1

[Arun C Murthy]

The call to System.currentTimeMillis was within that earlier (to be precise within, synchronized (scheduledCopies) ), I moved it outside the "synchronized (scheduledCopies)" and I think I moved it to the place where it should be in the loop.

Ok, I missed that one - sorry!

[Owen O'Malley]

This was caused by HADOOP-3297, which was only committed to 0.18. The confusion happened because Runping was running with it applied to 0.17.

[Devaraj Das]

I just committed this to the trunk.

[Hudson]

Integrated in Hadoop-trunk #492 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/492/)