regression: orte_submit_job() high error rates during startup

[marksantcroos]

With the latest master I get frequent errors during the launch of jobs where the launch callback returns -117 for the first failing jobs and then 69 for the remaining failing jobs.
Still trying characterise it fully. Seems to work fine for ~190 consecutive jobs and then starts to fail.

Also tried to find out what these errors maps to, but couldn't find that either...

The workload consists of very short jobs.

This is a regression in comparison to early december, didn't track it down to a specific commit yet.

[rhc54]

Error -117 corresponds to ORTE_ERR_SYS_LIMITS_PIPES (see orte/include/orte/constants.h), so it sounds like you are running out of file descriptors. I don't see an error 69 anywhere so I'm not sure where that is coming from.

I'd guess we are leaking file descriptors ☹️

[marksantcroos]

Hrm... bisect is turning out to be tricky, as the build was broken in that window.

I think the culprit is either:
eb67c2f (@rhc54)
or
de3de13 (@hppritcha)

Any clue?

[marksantcroos]

eb67c2f (@rhc54)

Does the "stil opal ignored" refers to that this code was not yet in effect at that date?

[rhc54]

yes - and it still isn't

[marksantcroos]

Ok, thanks, so that reduces it to one candidate then.

Now verifying that by cherry-picking the alps fix that came a couple of days later.

[rhc54]

Are you using the DVM? Or are you trying to run natively on the Cray? If the DVM, then I don't see how de3de13 could have had an impact as we wouldn't be using the Cray pmix component.

[marksantcroos]

Yes, this is about the dvm.

[rhc54]

I suspect you are chasing a ghost, then, as that component cannot impact the DVM.

[marksantcroos]

Hmmm, trying them both in isolation indeed doesn't allow me to recreate the problem.
So no ghosts ...

Then something must have survived in the build dir during the bisect, otherwise I can't really explain it.

Will dig further.

[rhc54]

You might want to update and try this again - there was a commit early this morning that addressed memory leaks (44c1ff6). I had to modify it slightly to fix the DVM (#2701)

[marksantcroos]

Thanks, tried the latest, but didn't work.

The good news is that I found the offending commit (dd491db), and this time I think it makes more sense.

The irony is that I upgraded my branch specifically because I needed that fix, as I didn't get any output of my jobs :-)
Didn't look yet what the exact issue is.

[rhc54]

Huh - let me know what you find. I'm not sure I see how that causes leaked file descriptors, but there may be something subtle in there.

[marksantcroos]

I didn't mean the change itself. But more that this enabled output again, which involves file descriptors at least.

[marksantcroos]

It seems orted is not closing fd's correctly.

I'm running the following payload:

 sh -c 'lsof -p $(pidof orted)'

Look at the increase for consecutive jobs:

> wc -l */rank.0/stdout|sort -n -k2
   7957 total
    122 1/rank.0/stdout
    127 2/rank.0/stdout
    154 3/rank.0/stdout
    162 4/rank.0/stdout
    172 5/rank.0/stdout
    177 6/rank.0/stdout
    189 7/rank.0/stdout
    197 8/rank.0/stdout
    212 9/rank.0/stdout
    217 10/rank.0/stdout
    226 11/rank.0/stdout
    235 12/rank.0/stdout
    244 13/rank.0/stdout
    231 14/rank.0/stdout
      0 15/rank.0/stdout
    231 16/rank.0/stdout
    253 17/rank.0/stdout
    253 18/rank.0/stdout
    252 19/rank.0/stdout
    257 20/rank.0/stdout
    266 21/rank.0/stdout
    278 22/rank.0/stdout
    280 23/rank.0/stdout
    293 24/rank.0/stdout
    292 25/rank.0/stdout
    301 26/rank.0/stdout
    314 27/rank.0/stdout
    321 28/rank.0/stdout
    327 29/rank.0/stdout
    333 30/rank.0/stdout
    342 31/rank.0/stdout
    344 32/rank.0/stdout
    355 33/rank.0/stdout

And if I look at the output of lsof of the 33rd job:

> grep std 33/rank.0/stdout |awk '{print $9}'|sort|uniq -c
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/1/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/1/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/10/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/10/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/11/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/11/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/12/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/12/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/13/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/13/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/14/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/14/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/15/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/15/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/16/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/16/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/17/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/17/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/18/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/18/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/19/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/19/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/2/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/2/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/20/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/20/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/21/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/21/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/22/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/22/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/23/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/23/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/24/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/24/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/25/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/25/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/26/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/26/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/27/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/27/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/28/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/28/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/29/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/29/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/3/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/3/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/30/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/30/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/31/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/31/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/32/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/32/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/33/rank.0/stderr
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/33/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/4/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/4/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/5/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/5/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/6/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/6/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/7/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/7/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/8/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/8/rank.0/stdout
      3 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/9/rank.0/stderr
      2 /lustre/atlas1/bip103/scratch/marksant1/tmp/output/9/rank.0/stdout

You can see that it still has multiple handles per stdout and stderr of the finished tasks.

Do you agree that this looks fishy?

[rhc54]

yeah, that isn't right - it looks like the IO channels aren't being released