|
Here are the related lines from the job tracker log:
2008-04-30 17:00:01,346 INFO org.apache.hadoop.mapred.JobTracker: Adding task 'task_200804301615_0003_m_000756_0' to tip tip_200804301615_0003_m_00075 The above lines show that there ere about 24 minutes time between the first notification of failuring to fetch the map output and the third notice. >2008-04-30 17:25:45,005 WARN org.apache.hadoop.mapred.TaskTracker: getMapOutput(task_200804301615_0003_m_000756_0,653) failed :
java.net.SocketException: Connection timed out > - > at org.mortbay.http.HttpOutputStream.write(HttpOutputStream.java:423) > at org.mortbay.jetty.servlet.ServletOut.write(ServletOut.java:54) "Connection timed out" error while writing indicates the root cause is mostly the same packet retransmission problem seen in As Runping mentioned that the map takes roughly 7mins and looking at the logs
Consider the following
i.e in total the reducer waits for 32.46 mins before sending the first failure notification.
i.e the total of 13mins between the 2 nd and 3 rd failure notifications. The problem is that in this case the read timeout becomes significant as compared to the total-backoff and the map runtime. Whoo, if a map output cannot be fetched for some reason, it will take at least 45minutes before the job tracker decides to re-execute the mapper? The above comment is our hypothesis. It matches incase of 2 nd and 3 rd attempts. Can you confirm the 1 st attempt. Plz check in the reducer logs to see the time required at the reducer to notify the first failure i.e time when the failure was reported - time when the fetch was first scheduled.
How do you know when the fetch of a map output was scheduled first? Why do you even need to confirm the time for first notification?
Look for the first occurrence of 'Copying task_200804301615_0003_m_000756_0 output from' in the reducer logs.
Agreed. But the main cause of the problem needs to detected and fixed. Its just the we should be sure that what we are fixing is really broken. It is pretty clear to me what is broken. Maybe till we have fetched 90% of the map outputs, we should do exponential backoff and after that we switch to fixed time smaller backoffs. But in the case of multiple jobs running in the cluster this policy might not be ideal (since the same tasktrackers might be serving outputs from multiple jobs).
There are two possible optimizations to help mitigate the problem.
Optimization 1 (At Job tracker) The Job tracker could decide on when to re execute a map based on the system For example, One possible strategy (Possible default vaues for x = 50%, y = 75%) Optimization 2 (At reduce task) The strategy is to categorize the time outs (while fetching map outputs) as Handling Connection Timeouts 1. Try connecting with the default timeout of 30s. Handling Read Timeouts Exponential Back Off Algorithm maxFetchRetriesPerMap = currentBackOff = (noFailedFetches <= maxFetchRetriesPerMap)
First notification after maxFetchRetriesPerMap attempts Example scenarios for Optimization 2 Case 1. Connect fails. Existing algorithm: New algorithm: Case 2. Connect successful, read fails. Existing algorithm: New algorithm: Attaching patch for review
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12384737/hadoop-3327.patch  against trunk revision 671563. +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. +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 failed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2745/testReport/ This message is automatically generated. Sorry this patch no longer applies cleanly. Pls regenerate the patch.
Sorry the assignment was updated by mistake
Patch for the latest trunk
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12385858/hadoop-3327-v1.patch against trunk revision 676069. +1 @author. The patch does not contain any @author tags. +1 tests included. The patch appears to include 3 new or modified tests. -1 patch. The patch command could not apply the patch. Console output: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2852/console This message is automatically generated. Attaching patch again for the latest trunk. Hopefully, third time lucky!!
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12386262/hadoop-3327-v2.patch against trunk revision 677470. +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. +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/2891/testReport/ This message is automatically generated. Did manual testing by hacking the code to simulate connection/read timeouts.
Sorry for the long turn-around on this one. There are two things that should be addressed:
1) Convert the error types to enum 2) There is a copy-paste error in an if-else clause (e.getClass() == ConnTimeoutException.class). The check should be for ReadTimeoutException in the else clause. Attaching patch after incorporating the review comments
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12386719/hadoop-3327-v3.patch against trunk revision 679202. +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. +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 failed core unit tests. +1 contrib tests. The patch passed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/2931/testReport/ This message is automatically generated. I just committed this. Thanks, Jothi!
Integrated in Hadoop-trunk #581 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/581/
) We observed that this patch, while reducing time for re execution of maps on failures, is impacting performance negatively for normal runs on regular clusters. Should we revert this patch till we come up with the correct solution?
I reverted the patch on both trunk and 0.19 branch.
Integrated in Hadoop-trunk #618 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/618/
) After discussion with Jothi and Devaraj, I propose the following approach :
1. If pendingCopies < 0.25 * numMaps, // towards the end of shuffle 2. If failure is because of ReadTimeOut, 3. At JT, Thoughts? Attaching a patch for review, while i continue my testing.
I have done simple tests with patch. Results are as follows:
Some more numbers:
These results show good improvement incase of fetch failures. And there is no performance degrading. test-patch result :
[exec]
[exec] -1 overall.
[exec]
[exec] +1 @author. The patch does not contain any @author tags.
[exec]
[exec] -1 tests included. The patch doesn't appear to include any new or modified tests.
[exec] Please justify why no tests are needed for this patch.
[exec]
[exec] +1 javadoc. The javadoc tool did not generate any warning messages.
[exec]
[exec] +1 javac. The applied patch does not increase the total number of javac compiler warnings.
[exec]
[exec] +1 findbugs. The patch does not introduce any new Findbugs warnings.
[exec]
[exec] +1 Eclipse classpath. The patch retains Eclipse classpath integrity.
[exec]
[exec]
It is not easy to write a testcase for this. All core and contrib unit tests passed on my machine. Looks good. A few points
Looks fine to me. We shouldn't have any new configuration overall.
Also, the change in JobInProgress is not required at this point IMO.
Patch with review comments incorporated.
Reduces the waitiing time between map output fetch re-tries during the end of the shuffle by notifying the JobTracker, aggressively.
ReadTimeOuts during shuffle are treated differently: Reducer notifies the JobTracker immediately for a readTimeout and backs off for more time. test-patch and ant tests passed on my machine.
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12399348/patch-3327-1.txt against trunk revision 740237. +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. +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 Eclipse classpath. The patch retains Eclipse classpath integrity. +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/3790/testReport/ This message is automatically generated. Sorry, I just realized that we can avoid the class for handling read timeout exceptions, and instead have a thread-local variable that's set whenever a read timeout is seen...
attaching patch with the change sugggested by Devaraj
-1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12399449/patch-3327-2.txt against trunk revision 740532. +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. +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 Eclipse classpath. The patch retains Eclipse classpath integrity. +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 failed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hadoop-Patch/3796/testReport/ This message is automatically generated. contrib-test failure TestAgentConfig.testInitAdaptors_vs_Checkpoint is not related to the patch
I just committed this. Thanks, Amareshwari!
I should note that this particular patch just handles read timeouts better. There is good scope of future work here and follow-up issues should be raised (for e.g., how best to determine when to kill a (faulty)map/reduce task during shuffle). Integrated in Hadoop-trunk #756 (See http://hudson.zones.apache.org/hudson/job/Hadoop-trunk/756/
)
Editorial pass over all release notes prior to publication of 0.21. bug
|
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
 |
|
Bug
Resolved
Major
Shuffling fetchers waited too long between map output fetch re-tries
A lot of exceptions like below in the reducer's log:
2008-04-30 17:27:32,155 WARN org.apache.hadoop.mapred.ReduceTask: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
at sun.net.www.http.ChunkedInputStream.fastRead(ChunkedInputStream.java:221)
at sun.net.www.http.ChunkedInputStream.read(ChunkedInputStream.java:662)
at java.io.FilterInputStream.read(FilterInputStream.java:116)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:2364)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:2359)
at org.apache.hadoop.mapred.MapOutputLocation.getFile(MapOutputLocation.java:205)
at org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.copyOutput(ReduceTask.java:828)
at org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.run(ReduceTask.java:777)
In the hadoop.log of the trask tracker hosting the map output, I saw a lot exception like:
2008-04-30 17:25:45,005 WARN org.apache.hadoop.mapred.TaskTracker: getMapOutput(task_200804301615_0003_m_000756_0,653) failed :
java.net.SocketException: Connection timed out
–
at org.mortbay.http.HttpOutputStream.write(HttpOutputStream.java:423)
at org.mortbay.jetty.servlet.ServletOut.write(ServletOut.java:54)
at org.apache.hadoop.mapred.TaskTracker$MapOutputServlet.doGet(TaskTracker.java:2353)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:427)
at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:475)
at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:567)
at org.mortbay.http.HttpContext.handle(HttpContext.java:1565)
at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:635)
at org.mortbay.http.HttpContext.handle(HttpContext.java:1517)
at org.mortbay.http.HttpServer.service(HttpServer.java:954)
at org.mortbay.http.HttpConnection.service(HttpConnection.java:814)
at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:981)
at org.mortbay.http.HttpConnection.handle(HttpConnection.java:831)
at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:244)
at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:357)
at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:534)
2008-04-30 17:25:45,005 WARN /: /mapOutput?job=job_200804301615_0003&map=task_200804301615_0003_m_000756_0&reduce=653:
java.lang.IllegalStateException: Committed
at org.mortbay.jetty.servlet.ServletHttpResponse.resetBuffer(ServletHttpResponse.java:212)
at org.mortbay.jetty.servlet.ServletHttpResponse.sendError(ServletHttpResponse.java:375)
at org.apache.hadoop.mapred.TaskTracker$MapOutputServlet.doGet(TaskTracker.java:2376)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:427)
at org.mortbay.jetty.servlet.WebApplicationHandler.dispatch(WebApplicationHandler.java:475)
at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:567)
at org.mortbay.http.HttpContext.handle(HttpContext.java:1565)
at org.mortbay.jetty.servlet.WebApplicationContext.handle(WebApplicationContext.java:635)
at org.mortbay.http.HttpContext.handle(HttpContext.java:1517)
at org.mortbay.http.HttpServer.service(HttpServer.java:954)
at org.mortbay.http.HttpConnection.service(HttpConnection.java:814)
at org.mortbay.http.HttpConnection.handleNext(HttpConnection.java:981)
at org.mortbay.http.HttpConnection.handle(HttpConnection.java:831)
at org.mortbay.http.SocketListener.handleConnection(SocketListener.java:244)
at org.mortbay.util.ThreadedServer.handle(ThreadedServer.java:357)
at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:534)