You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@tez.apache.org by Thaddeus Diamond <th...@gmail.com> on 2014/08/07 22:09:56 UTC

ShuffledMergedInput not started

Is there a race condition with input.start()?  I was under the impression I
didn't need to use it since it's in the initialize() method of
the LogicalIOProcessorRuntimeTask, but I saw this in one of the logs of a
task attempt.

2014-08-07 18:55:23,487 INFO [AsyncDispatcher event handler]
org.apache.tez.dag.history.HistoryEventHandler:
[HISTORY][DAG:dag_1407259853327_0029_2][Event:TASK_ATTEMPT_FINISHED]:
vertexName=8b013089-9aa9-4da3-9ab9-cca97fdf6b7c,
taskAttemptId=attempt_1407259853327_0029_2_01_000000_0,
startTime=1407437720449, finishTime=1407437723472, timeTaken=3023,
status=FAILED, diagnostics=Error: Failure while running
task:java.lang.IllegalStateException: Due to KeyValuesReader behavior you
must alternate calls to hasNext()/next()
at com.google.common.base.Preconditions.checkState(Preconditions.java:145)
at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.hasNext(VectorizedRowBatchFromKeyValueIterator.java:45)
at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:66)
at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:24)
at
com.hadapt.exec.tez.VectorOperatorProcessor.run(VectorOperatorProcessor.java:116)
at
org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:324)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:180)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:172)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1554)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:172)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:167)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)

Re: ShuffledMergedInput not started

Posted by Thaddeus Diamond <th...@gmail.com>.
Woops woops, god I'm terrible at cut/paste.  The stacktrace is fine:

2014-08-07 22:23:09,508 INFO [AsyncDispatcher event handler]
org.apache.tez.dag.history.HistoryEventHandler:
[HISTORY][DAG:dag_1407259853327_0031_2][Event:TASK_ATTEMPT_FINISHED]:
vertexName=e816a2e5-4d3a-49c2-9388-943b6dd08559,
taskAttemptId=attempt_1407259853327_0031_2_01_000003_1,
startTime=1407450189052, finishTime=1407450189502, timeTaken=450,
status=FAILED, diagnostics=Error: Failure while running
task:java.lang.IllegalStateException: Must start input before invoking this
method
at com.google.common.base.Preconditions.checkState(Preconditions.java:145)
at
org.apache.tez.runtime.library.input.ShuffledMergedInput.waitForInputReady(ShuffledMergedInput.java:160)
at
org.apache.tez.runtime.library.input.ShuffledMergedInput.getReader(ShuffledMergedInput.java:224)
at
org.apache.tez.runtime.library.input.ShuffledMergedInput.getReader(ShuffledMergedInput.java:65)
at
com.hadapt.exec.tez.VectorOperatorProcessor.run(VectorOperatorProcessor.java:110)
at
org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:324)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:180)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:172)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1554)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:172)
at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:167)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
, counters=Counters: 17, File System Counters, FILE: BYTES_READ=0, FILE:
BYTES_WRITTEN=0, FILE: READ_OPS=0, FILE: LARGE_READ_OPS=0, FILE:
WRITE_OPS=0, HDFS: BYTES_READ=0, HDFS: BYTES_WRITTEN=0, HDFS: READ_OPS=4,
HDFS: LARGE_READ_OPS=0, HDFS: WRITE_OPS=1,
org.apache.tez.common.counters.TaskCounter, REDUCE_INPUT_GROUPS=0,
REDUCE_INPUT_RECORDS=0, GC_TIME_MILLIS=4, CPU_MILLISECONDS=250,
PHYSICAL_MEMORY_BYTES=179834880, VIRTUAL_MEMORY_BYTES=1307996160,
COMMITTED_HEAP_BYTES=37814272



On Thu, Aug 7, 2014 at 4:36 PM, Hitesh Shah <hi...@apache.org> wrote:

> However, the exception stack trace is misleading with respect to the
> actual underlying problem. @Thad, could you file a bug in that regard?
>
> thanks
> — Hitesh
>
> On Aug 7, 2014, at 1:27 PM, Bikas Saha <bi...@hortonworks.com> wrote:
>
> > The processor is expected to call start() before using the input. That’s
> the recommended approach.
> >
> > The start() call that you see if an optimization that we do by calling
> start() implicitly once at the beginning of container execution. This hides
> some of the initial class loading latency for some inputs. This may
> disappear once those inputs can startup faster.
> >
> > You must call start() in your processor.
> >
> > Bikas
> >
> > From: Thaddeus Diamond [mailto:thaddeus.diamond@gmail.com]
> > Sent: Thursday, August 07, 2014 1:10 PM
> > To: user@tez.apache.org
> > Subject: ShuffledMergedInput not started
> >
> > Is there a race condition with input.start()?  I was under the
> impression I didn't need to use it since it's in the initialize() method of
> the LogicalIOProcessorRuntimeTask, but I saw this in one of the logs of a
> task attempt.
> >
> > 2014-08-07 18:55:23,487 INFO [AsyncDispatcher event handler]
> org.apache.tez.dag.history.HistoryEventHandler:
> [HISTORY][DAG:dag_1407259853327_0029_2][Event:TASK_ATTEMPT_FINISHED]:
> vertexName=8b013089-9aa9-4da3-9ab9-cca97fdf6b7c,
> taskAttemptId=attempt_1407259853327_0029_2_01_000000_0,
> startTime=1407437720449, finishTime=1407437723472, timeTaken=3023,
> status=FAILED, diagnostics=Error: Failure while running
> task:java.lang.IllegalStateException: Due to KeyValuesReader behavior you
> must alternate calls to hasNext()/next()
> >             at
> com.google.common.base.Preconditions.checkState(Preconditions.java:145)
> >             at
> com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.hasNext(VectorizedRowBatchFromKeyValueIterator.java:45)
> >             at
> com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:66)
> >             at
> com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:24)
> >             at
> com.hadapt.exec.tez.VectorOperatorProcessor.run(VectorOperatorProcessor.java:116)
> >             at
> org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:324)
> >             at
> org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:180)
> >             at
> org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:172)
> >             at java.security.AccessController.doPrivileged(Native Method)
> >             at javax.security.auth.Subject.doAs(Subject.java:415)
> >             at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1554)
> >             at
> org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:172)
> >             at
> org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:167)
> >             at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> >             at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >             at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >             at java.lang.Thread.run(Thread.java:744)
> >
> > CONFIDENTIALITY NOTICE
> > NOTICE: This message is intended for the use of the individual or entity
> to which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
>
>

Re: ShuffledMergedInput not started

Posted by Hitesh Shah <hi...@apache.org>.
However, the exception stack trace is misleading with respect to the actual underlying problem. @Thad, could you file a bug in that regard? 

thanks
— Hitesh

On Aug 7, 2014, at 1:27 PM, Bikas Saha <bi...@hortonworks.com> wrote:

> The processor is expected to call start() before using the input. That’s the recommended approach.
>  
> The start() call that you see if an optimization that we do by calling start() implicitly once at the beginning of container execution. This hides some of the initial class loading latency for some inputs. This may disappear once those inputs can startup faster.
>  
> You must call start() in your processor.
>  
> Bikas
>  
> From: Thaddeus Diamond [mailto:thaddeus.diamond@gmail.com] 
> Sent: Thursday, August 07, 2014 1:10 PM
> To: user@tez.apache.org
> Subject: ShuffledMergedInput not started
>  
> Is there a race condition with input.start()?  I was under the impression I didn't need to use it since it's in the initialize() method of the LogicalIOProcessorRuntimeTask, but I saw this in one of the logs of a task attempt.
>  
> 2014-08-07 18:55:23,487 INFO [AsyncDispatcher event handler] org.apache.tez.dag.history.HistoryEventHandler: [HISTORY][DAG:dag_1407259853327_0029_2][Event:TASK_ATTEMPT_FINISHED]: vertexName=8b013089-9aa9-4da3-9ab9-cca97fdf6b7c, taskAttemptId=attempt_1407259853327_0029_2_01_000000_0, startTime=1407437720449, finishTime=1407437723472, timeTaken=3023, status=FAILED, diagnostics=Error: Failure while running task:java.lang.IllegalStateException: Due to KeyValuesReader behavior you must alternate calls to hasNext()/next()
>             at com.google.common.base.Preconditions.checkState(Preconditions.java:145)
>             at com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.hasNext(VectorizedRowBatchFromKeyValueIterator.java:45)
>             at com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:66)
>             at com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:24)
>             at com.hadapt.exec.tez.VectorOperatorProcessor.run(VectorOperatorProcessor.java:116)
>             at org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:324)
>             at org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:180)
>             at org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:172)
>             at java.security.AccessController.doPrivileged(Native Method)
>             at javax.security.auth.Subject.doAs(Subject.java:415)
>             at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1554)
>             at org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:172)
>             at org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:167)
>             at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>             at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>             at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>             at java.lang.Thread.run(Thread.java:744)
> 
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to which it is addressed and may contain information that is confidential, privileged and exempt from disclosure under applicable law. If the reader of this message is not the intended recipient, you are hereby notified that any printing, copying, dissemination, distribution, disclosure or forwarding of this communication is strictly prohibited. If you have received this communication in error, please contact the sender immediately and delete it from your system. Thank You.

RE: ShuffledMergedInput not started

Posted by Bikas Saha <bi...@hortonworks.com>.
The processor is expected to call start() before using the input. That’s
the recommended approach.



The start() call that you see if an optimization that we do by calling
start() implicitly once at the beginning of container execution. This hides
some of the initial class loading latency for some inputs. This may
disappear once those inputs can startup faster.



You must call start() in your processor.



Bikas



*From:* Thaddeus Diamond [mailto:thaddeus.diamond@gmail.com]
*Sent:* Thursday, August 07, 2014 1:10 PM
*To:* user@tez.apache.org
*Subject:* ShuffledMergedInput not started



Is there a race condition with input.start()?  I was under the impression I
didn't need to use it since it's in the initialize() method of
the LogicalIOProcessorRuntimeTask, but I saw this in one of the logs of a
task attempt.



2014-08-07 18:55:23,487 INFO [AsyncDispatcher event handler]
org.apache.tez.dag.history.HistoryEventHandler:
[HISTORY][DAG:dag_1407259853327_0029_2][Event:TASK_ATTEMPT_FINISHED]:
vertexName=8b013089-9aa9-4da3-9ab9-cca97fdf6b7c,
taskAttemptId=attempt_1407259853327_0029_2_01_000000_0,
startTime=1407437720449, finishTime=1407437723472, timeTaken=3023,
status=FAILED, diagnostics=Error: Failure while running
task:java.lang.IllegalStateException: Due to KeyValuesReader behavior you
must alternate calls to hasNext()/next()

            at
com.google.common.base.Preconditions.checkState(Preconditions.java:145)

            at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.hasNext(VectorizedRowBatchFromKeyValueIterator.java:45)

            at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:66)

            at
com.hadapt.exec.tez.VectorizedRowBatchFromKeyValueIterator.next(VectorizedRowBatchFromKeyValueIterator.java:24)

            at
com.hadapt.exec.tez.VectorOperatorProcessor.run(VectorOperatorProcessor.java:116)

            at
org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:324)

            at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:180)

            at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable$1.run(TezTaskRunner.java:172)

            at java.security.AccessController.doPrivileged(Native Method)

            at javax.security.auth.Subject.doAs(Subject.java:415)

            at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1554)

            at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:172)

            at
org.apache.tez.runtime.task.TezTaskRunner$TaskRunnerCallable.call(TezTaskRunner.java:167)

            at java.util.concurrent.FutureTask.run(FutureTask.java:262)

            at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

            at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

            at java.lang.Thread.run(Thread.java:744)

-- 
CONFIDENTIALITY NOTICE
NOTICE: This message is intended for the use of the individual or entity to 
which it is addressed and may contain information that is confidential, 
privileged and exempt from disclosure under applicable law. If the reader 
of this message is not the intended recipient, you are hereby notified that 
any printing, copying, dissemination, distribution, disclosure or 
forwarding of this communication is strictly prohibited. If you have 
received this communication in error, please contact the sender immediately 
and delete it from your system. Thank You.