Grokbase Groups Pig user March 2009
FAQ
Hello Pig List,

I am now taking my (tested) pig script that will produce distinct counts and trying to apply it to real data. I am finding however, that though the map stage completes (100%), the reduce stage hangs at 97.77% and then fails to produce output.

It appears that the syslog contains notices of "threshold exceeded" before the ultimate failure...

2009-03-19 10:54:10,525 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 131343896(128265K) committed = 186449920(182080K) max = 186449920(182080K)
2009-03-19 10:54:18,150 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 131311248(128233K) committed = 186449920(182080K) max = 186449920(182080K)
2009-03-19 10:54:25,833 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 133580568(130449K) committed = 186449920(182080K) max = 186449920(182080K)

...

Does this mean that the Hadoop cluster requires tuning?

How can I avoid this memory error?



Regards,
Avram

Search Discussions

  • Olga Natkovich at Mar 19, 2009 at 9:24 pm
    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga
    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram
  • Avram Aelony at Mar 19, 2009 at 9:35 pm
    Thank you, Olga.
    Will reference http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Files and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga
    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram
  • Avram Aelony at Mar 20, 2009 at 6:46 pm
    Hi Pig List,

    After tinkering with the mapred.child.java.opts property -Xmx200m setting and trying 512, 1024, 2048 values (e.g. Xmx512m ), none of these seem to solve the problem. Map tasks complete 100% but Reduce tasks are killed never proceeding past 98.88% complete. I am setting the config changes in hadoop-site.xml.

    Can you provide guidance as to which parameters are relevant here and what settings to use?

    Thanks for your help,

    Avram



    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:35 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?


    Thank you, Olga.
    Will reference http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Files and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga
    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram
  • Yiping Han at Mar 20, 2009 at 7:07 pm
    Avram,

    Could you please post your syslog so we see the behavior of
    spillableMemoryManager?


    -Yiping

    On 3/20/09 11:46 AM, "Avram Aelony" wrote:

    Hi Pig List,

    After tinkering with the mapred.child.java.opts property -Xmx200m setting and
    trying 512, 1024, 2048 values (e.g. Xmx512m ), none of these seem to solve the
    problem. Map tasks complete 100% but Reduce tasks are killed never proceeding
    past 98.88% complete. I am setting the config changes in hadoop-site.xml.

    Can you provide guidance as to which parameters are relevant here and what
    settings to use?

    Thanks for your help,

    Avram



    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:35 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?


    Thank you, Olga.
    Will reference
    http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Fi
    les and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga
    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram
    ----------------------
    Yiping Han
    2MC 8127
    2811 Mission College Blvd.,
    Santa Clara, CA 95054
    (408)349-4403
    yhan@yahoo-inc.com
  • Avram Aelony at Mar 20, 2009 at 9:37 pm
    Hi Yiping,

    I'm attaching a screenshot PNG of the failures I see. Reduce task attempts were killed on 14 different slaves. Drilling down into each it looks like only slave hadoop09 has errors and SpillableMemoryManager complaints.

    It looks like there was a problem writing to file and SpillableMemoryManager problems..
    -Avram


    Details below..

    stderr logs

    Exception closing file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017
    org.apache.hadoop.ipc.RemoteException: java.io.IOException: Could not complete write to file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017 by DFSClient_attempt_200903201128_0001_r_000017_0
    at org.apache.hadoop.dfs.NameNode.complete(NameNode.java:357)
    at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:888)

    at org.apache.hadoop.ipc.Client.call(Client.java:715)
    at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:216)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.closeInternal(DFSClient.java:2726)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.close(DFSClient.java:2647)
    at org.apache.hadoop.dfs.DFSClient.close(DFSClient.java:215)
    at org.apache.hadoop.dfs.DistributedFileSystem.close(DistributedFileSystem.java:243)
    at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:1385)
    at org.apache.hadoop.fs.FileSystem.closeAll(FileSystem.java:234)
    at org.apache.hadoop.fs.FileSystem$ClientFinalizer.run(FileSystem.java:219)



    syslog logs

    2009-03-20 11:30:25,234 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    2009-03-20 11:30:25,691 INFO org.apache.hadoop.mapred.ReduceTask: ShuffleRamManager: MemoryLimit=157286400, MaxSingleShuffleLimit=39321600
    2009-03-20 11:30:25,742 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging on-disk files
    2009-03-20 11:30:25,743 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:30:25,746 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:30:25,747 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging in memory files
    2009-03-20 11:30:25,748 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:30:25,749 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:31:25,789 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:32:25,828 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:32:25,829 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:32:25,830 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:33:25,867 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 2 new map-outputs & number of known map outputs is 2
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 2 of 2 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 565463819 bytes (565463819 raw bytes) into Local-FS from attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 535596555 bytes (535596555 raw bytes) into Local-FS from attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:17,908 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:17,909 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:17,927 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 549733386 bytes (549733386 raw bytes) into Local-FS from attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:22,930 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:22,931 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:22,945 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 559085822 bytes (559085822 raw bytes) into Local-FS from attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:25,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 4 is already in progress
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:32,493 INFO org.apache.hadoop.mapred.ReduceTask: Read 535596555 bytes from map-output for attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:32,505 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:36,677 INFO org.apache.hadoop.mapred.ReduceTask: Read 565463819 bytes from map-output for attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:36,704 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:37,159 INFO org.apache.hadoop.mapred.ReduceTask: Read 549733386 bytes from map-output for attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:37,165 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:39,732 INFO org.apache.hadoop.mapred.ReduceTask: Read 559085822 bytes from map-output for attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:39,736 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:40,025 INFO org.apache.hadoop.mapred.ReduceTask: Closed ram manager
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: Interleaved on-disk merge complete: 4 files left.
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: In-memory merge complete: 0 files left.
    2009-03-20 11:34:40,027 INFO org.apache.hadoop.mapred.ReduceTask: Initiating final on-disk merge with 4 files
    2009-03-20 11:34:40,048 INFO org.apache.hadoop.mapred.Merger: Merging 4 sorted segments
    2009-03-20 11:34:46,445 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 4 segments left of total size: 2209879582 bytes
    2009-03-20 11:35:08,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 267255808(260992K) committed = 305987584(298816K) max = 477233152(466048K)
    2009-03-20 11:35:27,500 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 243009992(237314K) committed = 294715392(287808K) max = 477233152(466048K)
    2009-03-20 11:35:44,331 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 294715384(287807K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:35:50,850 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335507480(327644K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:36:05,033 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 256954008(250931K) committed = 338362368(330432K) max = 477233152(466048K)
    2009-03-20 11:36:23,460 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334921592(327071K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:40,251 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334995976(327144K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:56,912 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334744144(326898K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:13,779 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 336437688(328552K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:30,685 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341918504(333904K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:47,640 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334678160(326834K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:04,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335327104(327467K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:21,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340675816(332691K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:38,904 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339857856(331892K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:55,835 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341207224(333210K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:13,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339354528(331400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:30,443 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334435872(326597K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:47,444 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341849704(333837K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:04,424 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334251632(326417K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:21,451 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341015000(333022K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:38,279 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341475264(333471K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:55,194 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340923008(332932K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:12,195 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334079216(326249K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:28,862 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334112360(326281K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:45,700 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334632944(326789K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:02,883 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341260800(333262K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:20,318 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341771216(333760K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:37,514 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340517600(332536K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:54,644 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334972072(327121K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:11,395 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334300152(326464K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:28,308 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341909944(333896K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:45,328 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341787464(333776K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:02,035 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339700808(331739K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:19,021 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341705112(333696K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:35,810 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339760248(331797K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:53,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339696440(331734K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:10,266 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340463384(332483K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:27,750 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341859888(333847K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:45,126 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340981720(332989K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:02,601 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341606256(333599K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:19,765 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341982248(333967K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:36,654 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341968048(333953K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:54,131 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341402408(333400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:10,854 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334262696(326428K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:27,651 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339894880(331928K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:44,466 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335703624(327835K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:01,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335137016(327282K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:17,625 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335608344(327742K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:49:04,588 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334234728(326401K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:57:52,875 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 318525864(311060K) committed = 428867584(418816K) max = 477233152(466048K)
    2009-03-20 11:58:17,099 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334310872(326475K) committed = 428867584(418816K) max = 477233152(466048K)



    -----Original Message-----
    From: Yiping Han
    Sent: Friday, March 20, 2009 12:05 PM
    To: pig-user@hadoop.apache.org
    Subject: Re: low memory handler?

    Avram,

    Could you please post your syslog so we see the behavior of
    spillableMemoryManager?


    -Yiping

    On 3/20/09 11:46 AM, "Avram Aelony" wrote:

    Hi Pig List,

    After tinkering with the mapred.child.java.opts property -Xmx200m setting and
    trying 512, 1024, 2048 values (e.g. Xmx512m ), none of these seem to solve the
    problem. Map tasks complete 100% but Reduce tasks are killed never proceeding
    past 98.88% complete. I am setting the config changes in hadoop-site.xml.

    Can you provide guidance as to which parameters are relevant here and what
    settings to use?

    Thanks for your help,

    Avram



    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:35 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?


    Thank you, Olga.
    Will reference
    http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Fi
    les and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga
    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram
    ----------------------
    Yiping Han
    2MC 8127
    2811 Mission College Blvd.,
    Santa Clara, CA 95054
    (408)349-4403
    yhan@yahoo-inc.com
  • Benjamin Reed at Mar 20, 2009 at 10:06 pm
    are you running out of diskspace?

    ben

    Avram Aelony wrote:
    Hi Yiping,

    I'm attaching a screenshot PNG of the failures I see. Reduce task attempts were killed on 14 different slaves. Drilling down into each it looks like only slave hadoop09 has errors and SpillableMemoryManager complaints.

    It looks like there was a problem writing to file and SpillableMemoryManager problems..
    -Avram


    Details below..

    stderr logs

    Exception closing file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017
    org.apache.hadoop.ipc.RemoteException: java.io.IOException: Could not complete write to file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017 by DFSClient_attempt_200903201128_0001_r_000017_0
    at org.apache.hadoop.dfs.NameNode.complete(NameNode.java:357)
    at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:888)

    at org.apache.hadoop.ipc.Client.call(Client.java:715)
    at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:216)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.closeInternal(DFSClient.java:2726)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.close(DFSClient.java:2647)
    at org.apache.hadoop.dfs.DFSClient.close(DFSClient.java:215)
    at org.apache.hadoop.dfs.DistributedFileSystem.close(DistributedFileSystem.java:243)
    at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:1385)
    at org.apache.hadoop.fs.FileSystem.closeAll(FileSystem.java:234)
    at org.apache.hadoop.fs.FileSystem$ClientFinalizer.run(FileSystem.java:219)



    syslog logs

    2009-03-20 11:30:25,234 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    2009-03-20 11:30:25,691 INFO org.apache.hadoop.mapred.ReduceTask: ShuffleRamManager: MemoryLimit=157286400, MaxSingleShuffleLimit=39321600
    2009-03-20 11:30:25,742 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging on-disk files
    2009-03-20 11:30:25,743 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:30:25,746 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:30:25,747 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging in memory files
    2009-03-20 11:30:25,748 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:30:25,749 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:31:25,789 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:32:25,828 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:32:25,829 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:32:25,830 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:33:25,867 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 2 new map-outputs & number of known map outputs is 2
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 2 of 2 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 565463819 bytes (565463819 raw bytes) into Local-FS from attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 535596555 bytes (535596555 raw bytes) into Local-FS from attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:17,908 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:17,909 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:17,927 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 549733386 bytes (549733386 raw bytes) into Local-FS from attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:22,930 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:22,931 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:22,945 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 559085822 bytes (559085822 raw bytes) into Local-FS from attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:25,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 4 is already in progress
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:32,493 INFO org.apache.hadoop.mapred.ReduceTask: Read 535596555 bytes from map-output for attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:32,505 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:36,677 INFO org.apache.hadoop.mapred.ReduceTask: Read 565463819 bytes from map-output for attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:36,704 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:37,159 INFO org.apache.hadoop.mapred.ReduceTask: Read 549733386 bytes from map-output for attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:37,165 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:39,732 INFO org.apache.hadoop.mapred.ReduceTask: Read 559085822 bytes from map-output for attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:39,736 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:40,025 INFO org.apache.hadoop.mapred.ReduceTask: Closed ram manager
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: Interleaved on-disk merge complete: 4 files left.
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: In-memory merge complete: 0 files left.
    2009-03-20 11:34:40,027 INFO org.apache.hadoop.mapred.ReduceTask: Initiating final on-disk merge with 4 files
    2009-03-20 11:34:40,048 INFO org.apache.hadoop.mapred.Merger: Merging 4 sorted segments
    2009-03-20 11:34:46,445 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 4 segments left of total size: 2209879582 bytes
    2009-03-20 11:35:08,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 267255808(260992K) committed = 305987584(298816K) max = 477233152(466048K)
    2009-03-20 11:35:27,500 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 243009992(237314K) committed = 294715392(287808K) max = 477233152(466048K)
    2009-03-20 11:35:44,331 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 294715384(287807K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:35:50,850 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335507480(327644K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:36:05,033 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 256954008(250931K) committed = 338362368(330432K) max = 477233152(466048K)
    2009-03-20 11:36:23,460 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334921592(327071K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:40,251 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334995976(327144K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:56,912 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334744144(326898K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:13,779 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 336437688(328552K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:30,685 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341918504(333904K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:47,640 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334678160(326834K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:04,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335327104(327467K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:21,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340675816(332691K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:38,904 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339857856(331892K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:55,835 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341207224(333210K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:13,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339354528(331400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:30,443 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334435872(326597K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:47,444 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341849704(333837K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:04,424 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334251632(326417K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:21,451 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341015000(333022K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:38,279 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341475264(333471K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:55,194 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340923008(332932K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:12,195 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334079216(326249K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:28,862 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334112360(326281K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:45,700 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334632944(326789K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:02,883 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341260800(333262K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:20,318 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341771216(333760K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:37,514 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340517600(332536K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:54,644 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334972072(327121K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:11,395 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334300152(326464K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:28,308 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341909944(333896K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:45,328 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341787464(333776K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:02,035 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339700808(331739K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:19,021 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341705112(333696K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:35,810 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339760248(331797K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:53,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339696440(331734K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:10,266 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340463384(332483K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:27,750 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341859888(333847K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:45,126 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340981720(332989K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:02,601 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341606256(333599K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:19,765 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341982248(333967K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:36,654 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341968048(333953K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:54,131 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341402408(333400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:10,854 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334262696(326428K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:27,651 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339894880(331928K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:44,466 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335703624(327835K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:01,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335137016(327282K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:17,625 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335608344(327742K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:49:04,588 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334234728(326401K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:57:52,875 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 318525864(311060K) committed = 428867584(418816K) max = 477233152(466048K)
    2009-03-20 11:58:17,099 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334310872(326475K) committed = 428867584(418816K) max = 477233152(466048K)



    -----Original Message-----
    From: Yiping Han
    Sent: Friday, March 20, 2009 12:05 PM
    To: pig-user@hadoop.apache.org
    Subject: Re: low memory handler?

    Avram,

    Could you please post your syslog so we see the behavior of
    spillableMemoryManager?


    -Yiping


    On 3/20/09 11:46 AM, "Avram Aelony" wrote:

    Hi Pig List,

    After tinkering with the mapred.child.java.opts property -Xmx200m setting and
    trying 512, 1024, 2048 values (e.g. Xmx512m ), none of these seem to solve the
    problem. Map tasks complete 100% but Reduce tasks are killed never proceeding
    past 98.88% complete. I am setting the config changes in hadoop-site.xml.

    Can you provide guidance as to which parameters are relevant here and what
    settings to use?

    Thanks for your help,

    Avram



    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:35 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?


    Thank you, Olga.
    Will reference
    http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Fi
    les and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga

    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram

    ----------------------
    Yiping Han
    2MC 8127
    2811 Mission College Blvd.,
    Santa Clara, CA 95054
    (408)349-4403
    yhan@yahoo-inc.com
  • Avram Aelony at Mar 20, 2009 at 10:33 pm
    ...plenty of disk space...
    -A


    -----Original Message-----
    From: Benjamin Reed
    Sent: Friday, March 20, 2009 3:06 PM
    To: pig-user@hadoop.apache.org
    Subject: Re: low memory handler?

    are you running out of diskspace?

    ben

    Avram Aelony wrote:
    Hi Yiping,

    I'm attaching a screenshot PNG of the failures I see. Reduce task attempts were killed on 14 different slaves. Drilling down into each it looks like only slave hadoop09 has errors and SpillableMemoryManager complaints.

    It looks like there was a problem writing to file and SpillableMemoryManager problems..
    -Avram


    Details below..

    stderr logs

    Exception closing file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017
    org.apache.hadoop.ipc.RemoteException: java.io.IOException: Could not complete write to file /user/aaelony/agg_date_from_amf_20090209.csv/_temporary/_attempt_200903201128_0001_r_000017_0/part-00017 by DFSClient_attempt_200903201128_0001_r_000017_0
    at org.apache.hadoop.dfs.NameNode.complete(NameNode.java:357)
    at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:888)

    at org.apache.hadoop.ipc.Client.call(Client.java:715)
    at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:216)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
    at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
    at org.apache.hadoop.dfs.$Proxy1.complete(Unknown Source)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.closeInternal(DFSClient.java:2726)
    at org.apache.hadoop.dfs.DFSClient$DFSOutputStream.close(DFSClient.java:2647)
    at org.apache.hadoop.dfs.DFSClient.close(DFSClient.java:215)
    at org.apache.hadoop.dfs.DistributedFileSystem.close(DistributedFileSystem.java:243)
    at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:1385)
    at org.apache.hadoop.fs.FileSystem.closeAll(FileSystem.java:234)
    at org.apache.hadoop.fs.FileSystem$ClientFinalizer.run(FileSystem.java:219)



    syslog logs

    2009-03-20 11:30:25,234 INFO org.apache.hadoop.metrics.jvm.JvmMetrics: Initializing JVM Metrics with processName=SHUFFLE, sessionId=
    2009-03-20 11:30:25,691 INFO org.apache.hadoop.mapred.ReduceTask: ShuffleRamManager: MemoryLimit=157286400, MaxSingleShuffleLimit=39321600
    2009-03-20 11:30:25,742 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging on-disk files
    2009-03-20 11:30:25,743 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:30:25,746 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:30:25,747 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread started: Thread for merging in memory files
    2009-03-20 11:30:25,748 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:30:25,749 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:31:25,789 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:31:25,790 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:32:25,828 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:32:25,829 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:32:25,830 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:33:25,867 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 0 is already in progress
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:33:25,869 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 2 new map-outputs & number of known map outputs is 2
    2009-03-20 11:34:15,911 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 2 of 2 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 565463819 bytes (565463819 raw bytes) into Local-FS from attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:15,934 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 535596555 bytes (535596555 raw bytes) into Local-FS from attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:17,908 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:17,909 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:17,927 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 549733386 bytes (549733386 raw bytes) into Local-FS from attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:22,930 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 1 new map-outputs & number of known map outputs is 1
    2009-03-20 11:34:22,931 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 1 of 1 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:22,945 INFO org.apache.hadoop.mapred.ReduceTask: Shuffling 559085822 bytes (559085822 raw bytes) into Local-FS from attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:25,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Need another 4 map output(s) where 4 is already in progress
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0: Got 0 new map-outputs & number of known map outputs is 0
    2009-03-20 11:34:26,951 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Scheduled 0 of 0 known outputs (0 slow hosts and 0 dup hosts)
    2009-03-20 11:34:32,493 INFO org.apache.hadoop.mapred.ReduceTask: Read 535596555 bytes from map-output for attempt_200903201128_0001_m_000003_0
    2009-03-20 11:34:32,505 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:36,677 INFO org.apache.hadoop.mapred.ReduceTask: Read 565463819 bytes from map-output for attempt_200903201128_0001_m_000000_0
    2009-03-20 11:34:36,704 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:37,159 INFO org.apache.hadoop.mapred.ReduceTask: Read 549733386 bytes from map-output for attempt_200903201128_0001_m_000002_0
    2009-03-20 11:34:37,165 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:39,732 INFO org.apache.hadoop.mapred.ReduceTask: Read 559085822 bytes from map-output for attempt_200903201128_0001_m_000001_0
    2009-03-20 11:34:39,736 INFO org.apache.hadoop.mapred.ReduceTask: attempt_200903201128_0001_r_000017_0 Thread waiting: Thread for merging on-disk files
    2009-03-20 11:34:40,025 INFO org.apache.hadoop.mapred.ReduceTask: Closed ram manager
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: Interleaved on-disk merge complete: 4 files left.
    2009-03-20 11:34:40,026 INFO org.apache.hadoop.mapred.ReduceTask: In-memory merge complete: 0 files left.
    2009-03-20 11:34:40,027 INFO org.apache.hadoop.mapred.ReduceTask: Initiating final on-disk merge with 4 files
    2009-03-20 11:34:40,048 INFO org.apache.hadoop.mapred.Merger: Merging 4 sorted segments
    2009-03-20 11:34:46,445 INFO org.apache.hadoop.mapred.Merger: Down to the last merge-pass, with 4 segments left of total size: 2209879582 bytes
    2009-03-20 11:35:08,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 267255808(260992K) committed = 305987584(298816K) max = 477233152(466048K)
    2009-03-20 11:35:27,500 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 243009992(237314K) committed = 294715392(287808K) max = 477233152(466048K)
    2009-03-20 11:35:44,331 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 294715384(287807K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:35:50,850 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335507480(327644K) committed = 347406336(339264K) max = 477233152(466048K)
    2009-03-20 11:36:05,033 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 256954008(250931K) committed = 338362368(330432K) max = 477233152(466048K)
    2009-03-20 11:36:23,460 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334921592(327071K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:40,251 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334995976(327144K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:36:56,912 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334744144(326898K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:13,779 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 336437688(328552K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:30,685 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341918504(333904K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:37:47,640 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334678160(326834K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:04,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335327104(327467K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:21,508 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340675816(332691K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:38,904 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339857856(331892K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:38:55,835 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341207224(333210K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:13,114 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339354528(331400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:30,443 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334435872(326597K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:39:47,444 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341849704(333837K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:04,424 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334251632(326417K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:21,451 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341015000(333022K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:38,279 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341475264(333471K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:40:55,194 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340923008(332932K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:12,195 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334079216(326249K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:28,862 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334112360(326281K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:41:45,700 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334632944(326789K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:02,883 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341260800(333262K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:20,318 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341771216(333760K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:37,514 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340517600(332536K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:42:54,644 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334972072(327121K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:11,395 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334300152(326464K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:28,308 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341909944(333896K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:43:45,328 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341787464(333776K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:02,035 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339700808(331739K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:19,021 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341705112(333696K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:35,810 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339760248(331797K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:44:53,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339696440(331734K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:10,266 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340463384(332483K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:27,750 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341859888(333847K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:45:45,126 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 340981720(332989K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:02,601 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341606256(333599K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:19,765 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341982248(333967K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:36,654 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341968048(333953K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:46:54,131 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 341402408(333400K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:10,854 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334262696(326428K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:27,651 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 339894880(331928K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:47:44,466 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335703624(327835K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:01,206 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335137016(327282K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:48:17,625 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 335608344(327742K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:49:04,588 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334234728(326401K) committed = 420216832(410368K) max = 477233152(466048K)
    2009-03-20 11:57:52,875 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Collection threshold exceeded) init = 1441792(1408K) used = 318525864(311060K) committed = 428867584(418816K) max = 477233152(466048K)
    2009-03-20 11:58:17,099 INFO org.apache.pig.impl.util.SpillableMemoryManager: low memory handler called (Usage threshold exceeded) init = 1441792(1408K) used = 334310872(326475K) committed = 428867584(418816K) max = 477233152(466048K)



    -----Original Message-----
    From: Yiping Han
    Sent: Friday, March 20, 2009 12:05 PM
    To: pig-user@hadoop.apache.org
    Subject: Re: low memory handler?

    Avram,

    Could you please post your syslog so we see the behavior of
    spillableMemoryManager?


    -Yiping


    On 3/20/09 11:46 AM, "Avram Aelony" wrote:

    Hi Pig List,

    After tinkering with the mapred.child.java.opts property -Xmx200m setting and
    trying 512, 1024, 2048 values (e.g. Xmx512m ), none of these seem to solve the
    problem. Map tasks complete 100% but Reduce tasks are killed never proceeding
    past 98.88% complete. I am setting the config changes in hadoop-site.xml.

    Can you provide guidance as to which parameters are relevant here and what
    settings to use?

    Thanks for your help,

    Avram



    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:35 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?


    Thank you, Olga.
    Will reference
    http://hadoop.apache.org/core/docs/current/cluster_setup.html#Configuration+Fi
    les and try to specify more memory.

    Regards,
    Avram



    -----Original Message-----
    From: Olga Natkovich
    Sent: Thursday, March 19, 2009 2:21 PM
    To: pig-user@hadoop.apache.org
    Subject: RE: low memory handler?

    It looks like your tasks are configured to use 200 MB. This is usually
    not sufficient for large data processing. In general, you need at least
    500 MB, 1 GB recommended and if you have more memory on your machine,
    configuring more can further help your query execution. The amount of
    course depends on how much memory you have on your machines and how many
    map and reduce slots they have.

    Olga

    -----Original Message-----
    From: Avram Aelony
    Sent: Thursday, March 19, 2009 2:14 PM
    To: pig-user@hadoop.apache.org
    Subject: low memory handler?

    Hello Pig List,

    I am now taking my (tested) pig script that will produce
    distinct counts and trying to apply it to real data. I am
    finding however, that though the map stage completes (100%),
    the reduce stage hangs at 97.77% and then fails to produce output.

    It appears that the syslog contains notices of "threshold
    exceeded" before the ultimate failure...

    2009-03-19 10:54:10,525 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131343896(128265K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:18,150 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 131311248(128233K) committed =
    186449920(182080K) max = 186449920(182080K)
    2009-03-19 10:54:25,833 INFO
    org.apache.pig.impl.util.SpillableMemoryManager: low memory
    handler called (Usage threshold exceeded) init =
    1441792(1408K) used = 133580568(130449K) committed =
    186449920(182080K) max = 186449920(182080K)

    ...

    Does this mean that the Hadoop cluster requires tuning?

    How can I avoid this memory error?



    Regards,
    Avram

    ----------------------
    Yiping Han
    2MC 8127
    2811 Mission College Blvd.,
    Santa Clara, CA 95054
    (408)349-4403
    yhan@yahoo-inc.com

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupuser @
categoriespig, hadoop
postedMar 19, '09 at 9:14p
activeMar 20, '09 at 10:33p
posts8
users4
websitepig.apache.org

People

Translate

site design / logo © 2021 Grokbase