Mailing-List: contact dev-help@reef.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@reef.apache.org
Date: Mon, 17 Apr 2017 16:33:41 +0000 (UTC)
From: "Markus Weimer (JIRA)" <jira@apache.org>
To: dev@reef.apache.org
Message-ID: <JIRA.13064185.1492218116000.297457.1492446821910@Atlassian.JIRA>
In-Reply-To: <JIRA.13064185.1492218116000@Atlassian.JIRA>
References: <JIRA.13064185.1492218116000@Atlassian.JIRA> <JIRA.13064185.1492218116686@jira-lw-us.apache.org>
Subject: [jira] [Commented] (REEF-1778) The IIMRUResultHandler Dispose()
 method isn't allowed to complete before the job finishes.
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
archived-at: Mon, 17 Apr 2017 16:33:48 -0000


    [ https://issues.apache.org/jira/browse/REEF-1778?page=3Dcom.atlassian.=
jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D15971=
307#comment-15971307 ]=20

Markus Weimer commented on REEF-1778:
-------------------------------------

Thanks for reporting this!

I believe your analysis is spot-on. The `Task.Dispose()` method is guarante=
ed to complete right now. The sequence of events at the end of an IMRU Job =
is as follows, IIRC:

=C2=A0 * {{UpdateTaskHost}} determines that the job is done and {{return}}s=
.
  * On a Thread, {{TaskRuntime}} sends the {{ITask}}'s return value to {{Ta=
skStatus.SetResult()}} ({{TaskRuntime.cs}} line 103) which in turn triggers=
 a heartbeat ({{TaskStatus.cs}} line 127.=20
  * Receipt of this heartbeat causes the Driver to shutdown the job.
  * Meanwhile, Thread mentioned above is still busy working through the lin=
es after line 103 in {{TaskRuntime.cs}}, which includes calling the {{Dispo=
se}} method on the {{ITask}}, which eventually calls the {{Dispose}} method=
s in IMRU Tasks.

These last two steps create a race condition. If the roundtrip to the Drive=
r and back is faster than the work done in {{TaskRuntime.cs}} post-line 103=
, the Thread could be rudely interrupted.

Does this sound like a reasonable explanation for this bug? If so, what ide=
as do we have to remedy it? My first idea is to restructure {{TaskRuntime}}=
 such that {{Dispose}} is called before a result is send to the Driver. Any=
 other ideas?


> The IIMRUResultHandler Dispose() method isn't allowed to complete before =
the job finishes.
> -------------------------------------------------------------------------=
-----------------
>
>                 Key: REEF-1778
>                 URL: https://issues.apache.org/jira/browse/REEF-1778
>             Project: REEF
>          Issue Type: Bug
>          Components: IMRU, REEF.NET
>         Environment: YARN. Does not affect the local runtime.
>            Reporter: Rogan Carr
>
> The IIMRUResultHandler Dispose() method isn't allowed to complete before =
the job finishes when run on YARN. When running locally, this isn't an issu=
e. I have not tested a Mesos runtime.
> My hunch is that YARN is killing the container before Dispose() finishes.=
 If I had to guess, I think that the driver calls Dispose() is on the Updat=
eTaskHost (which calls it on the IIMRUResultHandler), and then the driver t=
ells YARN that the entire job is done, and then YARN kills all the containe=
rs before they have a chance to dispose.
> Whatever the case is, this looks like a race condition. I occasionally do=
 see my Dispose() actions successfully complete.
> -----------------------------------------
> [1] Log showing that IIMRUResultHandler.Dispose() did not finish. Here Di=
spose() is a for loop that writes a number and waits a second. It is suppos=
ed to count to 100, but only counts till 9 before the logs end.
> {noformat}
> ...
> INFO: receive a ReefMessage from Org.Apache.REEF.Common.Protobuf.ReefProt=
ocol.REEFMessage Driver at socket://100.119.200.14:9570.
> Org.Apache.REEF.Common.Runtime.Evaluator.ReefMessageProtoObserver Informa=
tion: 0 : 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Control protobuf to remove context MasterRootContext
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorRuntime Information: 0 =
: 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Handle Evaluator control message:  done_evaluator =3D null kill_eva=
luator =3D null stop_evaluator =3D null context_control =3D not null
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorRuntime Information: 0 =
: 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Send task control message to ContextManager
> Org.Apache.REEF.Common.Runtime.Evaluator.Context.ContextManager Informati=
on: 0 : 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: RemoveContext with id MasterRootContext
> Org.Apache.REEF.Common.Runtime.Evaluator.Context.ContextRuntime Warning: =
0 : 2017-04-14T15:48:09.5616766+00:00 0020
> WARNING: Shutting down an task because the underlying context is being cl=
osed.
> Org.Apache.REEF.Common.Runtime.Evaluator.Task.TaskRuntime Information: 0 =
: 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Trying to close Task IMRUMaster-0
> Org.Apache.REEF.Common.Runtime.Evaluator.Task.TaskRuntime Warning: 0 : 20=
17-04-14T15:48:09.5616766+00:00 0020
> WARNING: Trying to close an task that is in Done state. Ignored.
> Org.Apache.REEF.Common.Context.Defaults.DefaultContextStopHandler Informa=
tion: 0 : 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: DefaultContextStopHandler received for context: MasterRootContext
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorRuntime Information: 0 =
: 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Context stack is empty, done
> Org.Apache.REEF.Common.Runtime.Evaluator.HeartBeatManager Information: 0 =
: 2017-04-14T15:48:09.5616766+00:00 0020
> INFO: Triggered a heartbeat: EvaluatorHeartbeatProto: task_id=3D[], task_=
status=3D[], task_message=3D[], evaluator_status=3D[DONE], context_status=
=3D[], time
> stamp=3D[1492184889561], recoveryFlag =3D[False].
> Org.Apache.REEF.Common.Runtime.Evaluator.ReefMessageProtoObserver Informa=
tion: 0 : 2017-04-14T15:48:09.5929225+00:00 0005
> INFO: receive a ReefMessage from Org.Apache.REEF.Common.Protobuf.ReefProt=
ocol.REEFMessage Driver at socket://100.119.200.14:9570.
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorRuntime Information: 0 =
: 2017-04-14T15:48:09.5929225+00:00 0005
> INFO: Handle Evaluator control message:  done_evaluator =3D not null kill=
_evaluator =3D null stop_evaluator =3D null context_control =3D null
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorRuntime Information: 0 =
: 2017-04-14T15:48:09.5929225+00:00 0005
> INFO: Received ACK from Driver, shutting down Evaluator.
> Org.Apache.REEF.Common.Runtime.Evaluator.EvaluatorExitLogger Information:=
 0 : 2017-04-14T15:48:09.5929225+00:00 0001
> INFO: The Evaluator has successfully exited.
> Org.Apache.REEF.Evaluator.Evaluator Information: 0 : 2017-04-14T15:48:09.=
5929225+00:00 0001
> INFO: Evaluator is returned from Run()
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:10.0460051+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 1
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:11.0615866+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 2
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:12.0771779+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 3
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:13.0927401+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 4
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:14.1083243+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 5
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:15.1239021+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 6
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:16.1394801+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 7
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:17.1550601+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 8
> [name-of-class-deleted]`1 Information: 0 : 2017-04-14T15:48:18.1706423+00=
:00 0014
> INFO: IIMRUResultHandler Dispose Countdown: 9
> End of LogType:evaluator.stdout
> {noformat}


--
This message was sent by Atlassian JIRA
(v6.3.15#6346)