Launcher and worker statuses do not correctly indicate the underlying states

[terrytangyuan]

Launcher keeps crashing:

mpi-test-2-mpijob-launcher-lv2fx                                    1/1      CrashLoopBackOff             2          1m
mpi-test-2-mpijob-worker-0                                             1/1      Running                                0          1m
mpi-test-2-mpijob-worker-1                                             1/1       Running                                0          1m

However, from the launcher's log, one of the worker is the one that's failing and is killed (later found that it was due to OOM)

-------------------------------------------------------
Primary job  terminated normally, but 1 process returned
a non-zero exit code. Per user-direction, the job has been aborted.
-------------------------------------------------------
--------------------------------------------------------------------------
mpirun.real noticed that process rank 1 with PID 39 on node mpi-test-2-mpijob-worker-1 exited on signal 9 (Killed).
--------------------------------------------------------------------------

Here's the description for launcher job which does not indicate any abnormal events:

Events:
  Type    Reason            Age   From            Message
  ----    ------            ----  ----            -------
  Normal  SuccessfulCreate  14m   job-controller  Created pod: mpi-test-mpijob-launcher-m8kw6

The above problems could potentially be addressed by #12 (currently mpirun does not give us helpful error messages so maybe PMIx is a better here) and #54 (currently only launcher pod is shown as failing but the workers are actually failing). There are other solutions too but I just wanted to link to other existing issues.

[czheng94]

Any update on this issue?
I have experienced the same problem. Some workers went OOM, and the launcher failed in the end with its pod deleted by kube batch Job.
The logs in the launcher also doesn't report any OOM error from workers.

[terrytangyuan]

@czheng94 No I didn't get a chance to dig into the problem yet. This is a different issue than the log issue though.

[czheng94]

@terrytangyuan Yeah this is a separate issue.
According to my understanding, if MPI doesn't report OOM from workers to launcher (which is probably the current status), StatefulSets will just directly recreate the worker pod and launcher will restart, MPIJob will just keep failing until it exceeds 'backOffLimit'.

[terrytangyuan]

@czheng94 Yes that will happen which is problematic and often waste resources. We should probably check the status regularly and report to launcher.

[gaocegege]

Is there an reproducible case? I can help.

[gaocegege]

/kind bug
/priority p0

[czheng94]

Any updates on this issue?

From my side, it seems like the workers are not even failing.

An example failure case can be generated with this jobspec:

apiVersion: kubeflow.org/v1alpha2
kind: MPIJob
metadata:
  name: tensorflow-mnist
spec:
  backoffLimit: 0
  slotsPerWorker: 1
  cleanPodPolicy: None
  mpiReplicaSpecs:
    Launcher:
      replicas: 1
      template:
        spec:
          containers:
          - image: horovod-cpu:latest
            name: mpi-launcher
            command:
            - mpirun
            args:
            - -np
            - "2"
            - --allow-run-as-root
            - -bind-to
            - none
            - -map-by
            - slot
            - -x
            - LD_LIBRARY_PATH
            - -x
            - PATH
            - -mca
            - pml
            - ob1
            - -mca
            - btl
            - ^openib
            - python
            - /examples/tensorflow_mnist.py
            resources:
              limits:
                cpu: 1
                memory: 2Gi
    Worker:
      replicas: 2
      template:
        spec:
          containers:
          - command:
            - ""
            image: horovod-cpu:latest
            name: mpi-worker
            resources:
              limits:
                cpu: 0.1
                memory: 100M

If you describe the statefulset, you can only see these events

Events:
  Type    Reason            Age   From                    Message
  ----    ------            ----  ----                    -------
  Normal  SuccessfulCreate  11m   statefulset-controller  create Pod tensorflow-mnist-worker-0 in StatefulSet tensorflow-mnist-worker successful
  Normal  SuccessfulCreate  11m   statefulset-controller  create Pod tensorflow-mnist-worker-1 in StatefulSet tensorflow-mnist-worker successful

What's really happening here (at least for my case) is that the mpi daemon process in the workers initiated by the launcher is killed by linux OOM killer (this behavior may be dependent on the OS distribution of user's image). This is why launcher is saying exited on signal 9 (Killed), because it's kill -9ed inside the container. No error will be exposed into the pod level at all.

IMO, exited on signal 9 (Killed) in the launcher mpirun logs is already telling something about the root cause, it's just not that explicit. If the worker process is killed by signal 9, most likely it is an OOM.

If you exec into the container and run dmesg you'll see

$ kubectl exec -it tensorflow-mnist-worker-0 -- dmesg | grep -i 'killed process'
[2170324.940239] Killed process 32247 (main.py) total-vm:3845336kB, anon-rss:1033916kB, file-rss:131232kB
[2172517.618996] Killed process 22505 (main.py) total-vm:3856648kB, anon-rss:1033896kB, file-rss:131960kB
[2172603.619371] Killed process 30299 (main.py) total-vm:3856660kB, anon-rss:1033372kB, file-rss:131748kB
[2177288.072349] Killed process 31666 (main.py) total-vm:3922196kB, anon-rss:1032580kB, file-rss:131224kB
[2177829.731555] Killed process 13462 (main.py) total-vm:3921936kB, anon-rss:1032408kB, file-rss:131568kB
[2178619.599900] Killed process 15186 (main.py) total-vm:3922184kB, anon-rss:1032308kB, file-rss:131400kB

$ kubectl exec -it tensorflow-mnist-worker-0 -- dmesg | grep -i 'out of memory' 
[2170324.936956] Memory cgroup out of memory: Kill process 32247 (main.py) score 116 or sacrifice child
[2172517.616288] Memory cgroup out of memory: Kill process 22505 (main.py) score 117 or sacrifice child
[2172603.612790] Memory cgroup out of memory: Kill process 30299 (main.py) score 116 or sacrifice child
[2177288.066086] Memory cgroup out of memory: Kill process 31666 (main.py) score 115 or sacrifice child
[2177829.728769] Memory cgroup out of memory: Kill process 13462 (main.py) score 115 or sacrifice child
[2178619.596774] Memory cgroup out of memory: Kill process 15186 (main.py) score 115 or sacrifice child

Therefore, a dirty hack to solve this problem can be to always run these commands into the workers before scaling down replicas in the statefulset to 0, and check if there are processes killed because of OOM.

[terrytangyuan]

@czheng94 Thanks for digging into this! I agree it’s hacky solution but at least this will correct the status for such situation.