flux-wreckrun hangs with many tasks

[grondo]

Running verbose, flux-wreckrun should print job state update for each lwj.state transition reserved->starting->running->complete -- however, some of these are missing in larger runs:

A working 512 task case:

$ time flux wreckrun -v -n512 /bin/true
wreckrun: 0.005s: Sending LWJ request for 512 tasks (cmdline "/bin/true")
wreckrun: 0.012s: Registered jobid 1
wreckrun: Allocating 512 tasks across 2304 available nodes..
wreckrun: tasks per node: node[0-511]: 1
wreckrun: 0.109s: Sending run event
wreckrun: 0.302s: State = reserved
wreckrun: 5.084s: State = starting
wreckrun: 5.637s: State = running
wreckrun: 6.300s: State = complete
wreckrun: tasks [0-511]: exited with exit code 0
wreckrun: All tasks completed successfully.

vs a suspicious run of the same size:

$ time flux wreckrun -v -n512 /bin/true
wreckrun: 0.004s: Sending LWJ request for 512 tasks (cmdline "/bin/true")
wreckrun: 0.009s: Registered jobid 2
wreckrun: Allocating 512 tasks across 2304 available nodes..
wreckrun: tasks per node: node[0-511]: 1
wreckrun: 0.109s: Sending run event
wreckrun: 2.697s: State = complete
wreckrun: tasks [0-511]: exited with exit code 0
wreckrun: All tasks completed successfully.

[grondo]

If the complete state is missed, then job will hang:

$ time flux wreckrun -v -n2304 /bin/true
wreckrun: 0.005s: Sending LWJ request for 2304 tasks (cmdline "/bin/true")
wreckrun: 0.011s: Registered jobid 4
wreckrun: Allocating 2304 tasks across 2304 available nodes..
wreckrun: tasks per node: node[0-2303]: 1
wreckrun: 0.613s: Sending run event
/* hang */

the job is complete however:

$ flux kvs get lwj.4.state
complete

[garlick]

To see if it's a general problem with KVS watch versus a problem downstream, you might try running something like this on the side

$ flux kvs watch lwj.6.state

and see if it transitions through the states that you expect.

[grondo]

Good idea! I'm still verifying that lwj kvs state is sane

[grondo]

The separate flux kvs watch worked fine: (this was with 36,834 tasks)

$ flux kvs watch lwj.8.state
NULL
"reserved"
"starting"
"running"
"complete"

Perhaps what is happening is that the single reactor loop in flux-wreckrun is congested with the kz callbacks.. not sure yet.

[garlick]

Well those messages ought to be queued until somebody reads them no matter how busy the reactor is in the mean time. I'm not sure what situation would lead to them being dropped...

[SteVwonder]

To me, it doesn't seem like the events are being dropped. If events were being dropped, I would expect to see the first state, some missing states, and then the final state (e.g., State = reserved and then State = complete). What we see is just the last state.

What it seems like to me is that the kvs watch is not fully registering until the job has already progressed into the running or complete state. If that is the case, maybe going through the JSC would fix it?

[garlick]

@grondo should confirm but you may have nailed it! The kvswatcher on the state seems to be instantiated after the program is launched in flux-wreckrun. Maybe this can be trivially fixed by watching the state before sending the wrexec.run event.

[SteVwonder]

One thing is still puzzling me. If it is the case that the KVS watch is only being created after the job has completed, shouldn't the kvs cb function be called immediately with "complete" as the current value? From the kvs.h comments:

/* kvs_watch* is like kvs_get* except the registered callback is called
 * to set the value.  It will be called immediately to set the initial
 * value and again each time the value changes.

In one of @grondo's examples above, no states are registered. So maybe in that specific case, wreckrun hangs before even setting the kvs watch? Ormaybe the kvs watch is only instantiated after the job archival has happened? If the kvs watch is set to the lwj-active directory, then this would surely cause problems. If it is set to the lwj directory, then I don't see why it would be a problem.

[grondo]

Sorry guys, I didn't mean to leave this vague issue for you to speculate on! I just wanted to capture what I was seeing before heading out for first week of school shenanigans.

@garlick, I didn't mean to imply that the reactor was dropping the state changes, but more generally flux-wreckrun or lua bindings is losing them, sorry for the confusion.

I actually think @garlick was onto something when he asked if lua bindings use kvs_watch_once vs kvs_watch, and I think they may. That is especially bad when the reactor is busy because the callback may be sitting for awhile without being handled and this is when state transitions could be missed.

Regardless, moving the kvs_watch call up in flux-wreckrun is definitely required, but probably also a band-aid to the flux-lua bindings

[grondo]

I actually think @garlick was onto something when he asked if lua bindings use kvs_watch_once vs kvs_watch

Eh, nevermind. I forgot about the kvswatcher abstraction in the bindings, which use kvs_watch() directly (I think, been awhile since I've poked around in here)

[grondo]

I can verify that moving the run event after all watches are sett up does solve the problem similar to the first case above (some events missed) as @SteVwonder guessed. Now I'm remembering this was done on purpose on the theory that the run event should be issued as soon as possible since the frontend tool (flux-wreckrun) is not required for a functional run of a job. Also as @SteVwonder suggested, even if the kvs_watch isn't called until after the job is complete, the tool should still get that final state and note that the job is done.

Even with the run event issued after reactor setup, I'm still seeing cases where wreckrun appears to hang (no states are returned) I've updated the issue description reflecting the new focus of this report

[grondo]

closed by #1988