hadoop-common-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Arun C Murthy (JIRA)" <j...@apache.org>
Subject [jira] Updated: (HADOOP-3604) Reduce stuck at shuffling phase
Date Wed, 25 Jun 2008 07:04:44 GMT

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

Arun C Murthy updated HADOOP-3604:
----------------------------------

    Attachment: HADOOP-3604_1_20080624.patch

So it looks like a bug in the jvm causing a lock-up when 2 or more threads call 'JniEnv::GetDirectBufferAddress'
to get the direct-buffer address in the JNI layer, especially when the first call is initializing
the direct-buffer address... 

{noformat}
----------------- 22126 -----------------
22190 0xffffe410 ????????
0x00000002 ????????
0x064e5344 _ZN5Mutex28lock_without_safepoint_checkEv + 0x44
0x06557f57 _ZN20SafepointSynchronize5blockEP10JavaThread + 0xd7
0x0639bfd5 lookupDirectBufferClasses + 0x245
0x0639d5d2 _Z29initializeDirectBufferSupportP7JNIEnv_P10JavaThread + 0x192
0x0639c149 jni_GetDirectBufferAddress + 0x79
0xcf9fdf90 Java_org_apache_hadoop_io_compress_lzo_LzoDecompressor_decompressBytesDirect +
0xd0
0xf4d863aa * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompressBytesDirect(int)
bci:0 (Interpreted frame)
0xf4d7ede9 * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompress(byte[], int, int)
bci:116 line:273 (Interpreted frame)
0xf4d7f2c5 * org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(byte[], int,
int) bci:49 line:75 (Interpreted frame)
0xf4d7ede9 * org.apache.hadoop.io.compress.DecompressorStream.read(byte[], int, int) bci:39
line:74 (Interpreted frame)
0xf4d7ede9 * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.getMapOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation,
org.apache.hadoop.fs.Path) bci:549 line:1141 (Interpreted frame)
0xf4d7eda7 * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.copyOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation)
bci:181 line:976 (Interpreted frame)
0xf4d7ee2b * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.run() bci:93
line:925 (Interpreted frame)

----------------- 22176 -----------------
0xffffe410  ????????
0x00000ffc  ????????
0x0639c149  jni_GetDirectBufferAddress + 0x79
0xcf9fdf90  Java_org_apache_hadoop_io_compress_lzo_LzoDecompressor_decompressBytesDirect +
0xd0
0xf4d863aa  * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompressBytesDirect(int)
bci:0 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompress(byte[], int, int)
bci:116 line:273 (Interpreted frame)
0xf4d7f2c5  * org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(byte[], int,
int) bci:49 line:75 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.io.compress.DecompressorStream.read(byte[], int, int) bci:39
line:74 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.getMapOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation,
org.apache.hadoop.fs.Path) bci:549 line:1141 (Interpreted frame)
0xf4d7eda7  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.copyOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation)
bci:181 line:976 (Interpreted frame)
0xf4d7ee2b  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.run() bci:93
line:925 (Interpreted frame)

----------------- 22172 -----------------
0xffffe410  ????????
0x00000ffc  ????????
0x0639c149  jni_GetDirectBufferAddress + 0x79
0xcf9fdf90  Java_org_apache_hadoop_io_compress_lzo_LzoDecompressor_decompressBytesDirect +
0xd0
0xf4d863aa  * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompressBytesDirect(int)
bci:0 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.io.compress.lzo.LzoDecompressor.decompress(byte[], int, int)
bci:116 line:273 (Interpreted frame)
0xf4d7f2c5  * org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(byte[], int,
int) bci:49 line:75 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.io.compress.DecompressorStream.read(byte[], int, int) bci:39
line:74 (Interpreted frame)
0xf4d7ede9  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.getMapOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation,
org.apache.hadoop.fs.Path) bci:549 line:1141 (Interpreted frame)
0xf4d7eda7  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.copyOutput(org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputLocation)
bci:181 line:976 (Interpreted frame)
0xf4d7ee2b  * org.apache.hadoop.mapred.ReduceTask$ReduceCopier$MapOutputCopier.run() bci:93
line:925 (Interpreted frame)

{noformat}

We synchronized access to 'JniEnv::GetDirectBufferAddress'... voila!

Here is a patch which does fine-grained locking of just the call to JniEnv::GetDirectBufferAddress,
it has minimal performance impact and we see a substantial improvement in GridMix with compression
on for intermediate map-outputs and no more lockups, whee! *smile*

I'm hoping for a response from the post of the java forum...

> Reduce stuck at shuffling phase
> -------------------------------
>
>                 Key: HADOOP-3604
>                 URL: https://issues.apache.org/jira/browse/HADOOP-3604
>             Project: Hadoop Core
>          Issue Type: Bug
>          Components: mapred
>    Affects Versions: 0.18.0
>            Reporter: Runping Qi
>            Assignee: Arun C Murthy
>            Priority: Blocker
>             Fix For: 0.18.0
>
>         Attachments: HADOOP-3604_0_20080623.patch, HADOOP-3604_1_20080624.patch, HADOOP-3604_1_20080624.patch,
stack.txt
>
>
> I was running gridmix with Hadoop 0.18.
> I set the map output compression to true.
> Most of the jobs completed just fine.
> Three jobs, however, got stuck.
> Each has one reducer stuck at shuffling phase.
> Here is the log:
> 2008-06-20 00:06:01,264 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM
Metrics with processName=SHUFFLE, sessionId=
> 2008-06-20 00:06:01,415 INFO org.apache.hadoop.streaming.PipeMapRed: PipeMapRed exec
[/bin/cat]
> 2008-06-20 00:06:01,463 INFO org.apache.hadoop.mapred.ReduceTask: ShuffleRamManager:
MemoryLimit=134217728, MaxSingleShuffleLimit=33554432
> 2008-06-20 00:06:01,474 INFO org.apache.hadoop.util.NativeCodeLoader: Loaded the native-hadoop
library
> 2008-06-20 00:06:01,475 INFO org.apache.hadoop.io.compress.zlib.ZlibFactory: Successfully
loaded & initialized native-zlib library
> 2008-06-20 00:06:01,476 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,477 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,477 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,478 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,478 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,486 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,486 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,487 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,487 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,488 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,488 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,489 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,489 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,489 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,493 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,496 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,496 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,496 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,497 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,497 INFO org.apache.hadoop.io.compress.CodecPool: Got brand-new decompressor
> 2008-06-20 00:06:01,500 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Thread started: Thread for merging on-disk files
> 2008-06-20 00:06:01,500 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Thread waiting: Thread for merging on-disk files
> 2008-06-20 00:06:01,502 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Need another 270 map output(s) where 0 is already in progress
> 2008-06-20 00:06:01,503 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Thread started: Thread for merging in memory files
> 2008-06-20 00:06:01,503 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0:
Got 0 new map-outputs & number of known map outputs is 0
> 2008-06-20 00:06:01,504 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
> 2008-06-20 00:06:06,654 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0:
Got 269 new map-outputs & number of known map outputs is 269
> 2008-06-20 00:06:06,656 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200806192318_0450_r_000016_0
Scheduled 229 of 269 known outputs (0 slow hosts and 40 dup hosts)
> 2008-06-20 00:06:07,163 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 846183 bytes
(210104 raw bytes) into RAM-FS from attempt_200806192318_0450_m_000089_0
> 2008-06-20 00:06:07,163 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 820890 bytes
(204371 raw bytes) into RAM-FS from attempt_200806192318_0450_m_000083_0
> 2008-06-20 00:06:07,166 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 835672 bytes
(208085 raw bytes) into RAM-FS from attempt_200806192318_0450_m_000122_0

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message