Encoding failed due to server load - ffmpeg status 137

[Matthias Vollroth]

Dear all,

we are currently running a 3 node vm cluster with OC 6 and the standard workflow "process upon upload and schedule".

We are facing encoding errors especially when transcoding big files or parallel encodings (it mostly happens with 720p and 1080p encodings). Worker logs are pointing to an error: "Encoder exited abnormally with status 137", which means ffmpeg is killed with signal 9 (sigkill).

Our worker node got 24 cores and 128 gb ram - so there shouldnt be any ressource problem, but it seems that the ffmpeg job literally consumes more ressources than the server has and therfore the ffmpeg job gets killed by the system and the encoding process failed.

We tried out "org.opencastproject.job.load.acceptexceeding=false" without any improving. Do I have to configure special job loads?

Any idea or hint how to change that behavior?

Any help is appreciated.

Thanks in advance,

Matthias

[Rute Santos]

Hi Matthias,

    org.opencastproject.job.load.acceptexceeding is used to tell a node to accept a job that have its job load greater than the maximum node capacity so it doesn't help in your case.

    What you probably want to do is to limit the number of encoding jobs running at the same time, which can be done by specifying job loads in the encoding profile configuration found in etc/encodings (something like 'profile.PROFILE_NAME.jobload=2.0'). You will need to do some calculations to get the right number, considering how many encoding jobs you want to run simultaneously.

    As an example, our workers have 32 cores and our most intensive encoding jobs produce 4 outputs using the process-smil operation, which encodes all in parallel. We thus have 4 encoding profiles, each has a job load of 4.0 and, in etc/org.opencastproject.composer.impl.ComposerServiceImpl.cfg we have 'job.load.factor.process.smil=0.5', so each encoding job has a job load of 4 x 4.0 * 0.5 = 8.0, which limits the node to run 4 of those jobs concurrently at any given time (32 cores/8.0).

    I hope this helps!

    Thanks,

    Rute

    Harvard-DCE

--
To unsubscribe from this group and stop receiving emails from it, send an email to users+un...@opencast.org.

[Matthias Vollroth]

Hi Rute,

Thanks a lot for your swift response and the forwarded information - i will have a look into that.

Additionally we are facing negative job loads - for example:

• | WARN  | (EncoderEngine:234) - Error while encoding {video=/srv/opencast/workspace/mediapackage/762bdab0-b48c-4cc0-b9fb-e6fe266ff285/47f259e2-f281-4d37-a517-d2dcec79b2f1/xxx_S2R1.mp4}  using profile 'adaptive-1080p.http'
  org.opencastproject.composer.api.EncoderException: Encoder exited abnormally with status 137
      at org.opencastproject.composer.impl.EncoderEngine.process(EncoderEngine.java:228)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.composer.impl.ComposerServiceImpl.encode(ComposerServiceImpl.java:369)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.composer.impl.ComposerServiceImpl.process(ComposerServiceImpl.java:1368)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.job.api.AbstractJobProducer$JobRunner.call(AbstractJobProducer.java:314)[47:opencast-common:6.0.0.SNAPSHOT]
      at org.opencastproject.job.api.AbstractJobProducer$JobRunner.call(AbstractJobProducer.java:273)[47:opencast-common:6.0.0.SNAPSHOT]
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_222]
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_222]
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_222]
      at java.lang.Thread.run(Thread.java:748)[:1.8.0_222]

• | DEBUG | (ServiceRegistryJpaImpl:940) - 20977 Removing from load cache: Job 35045, type org.opencastproject.composer, status FAILED
  | DEBUG | (ServiceRegistryJpaImpl:948) - 20977 Current host load: -146.80022
  | DEBUG | (ServiceRegistryJpaImpl:2652) - Try to get the services in WARNING or ERROR state triggered by this job -853662090 failed

Iam wondering where that comes from? Maybe we get that terminated by your hint to define jobloads in the encoding profile...

Thanks and best regards,

Matthias

[Stephen Marquard]

Hi Matthias,

It looks like you're running Opencast 6.0. I'd suggest running the latest 6 release, 6.6, or else 6.x branch if you're building from source.

The negative host load is a definite sign of a bug, and there are quite a few job load dispatching fixes in 6.x.

Regards

Stephen

---

From: Matthias Vollroth <thd.ma...@gmail.com>
Sent: Thursday, 24 October 2019 17:06
To: us...@opencast.org <us...@opencast.org>
Subject: Re: [OC Users] Encoding failed due to server load - ffmpeg status 137

 

Hi Rute,

Thanks a lot for your swift response and the forwarded information - i will have a look into that.

Additionally we are facing negative job loads - for example:

• | WARN  | (EncoderEngine:234) - Error while encoding {video=/srv/opencast/workspace/mediapackage/762bdab0-b48c-4cc0-b9fb-e6fe266ff285/47f259e2-f281-4d37-a517-d2dcec79b2f1/xxx_S2R1.mp4}  using profile 'adaptive-1080p.http'
  org.opencastproject.composer.api.EncoderException: Encoder exited abnormally with status 137
      at org.opencastproject.composer.impl.EncoderEngine.process(EncoderEngine.java:228)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.composer.impl.ComposerServiceImpl.encode(ComposerServiceImpl.java:369)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.composer.impl.ComposerServiceImpl.process(ComposerServiceImpl.java:1368)[49:opencast-composer-ffmpeg:6.0.0.SNAPSHOT]
      at org.opencastproject.job.api.AbstractJobProducer$JobRunner.call(AbstractJobProducer.java:314)[47:opencast-common:6.0.0.SNAPSHOT]
      at org.opencastproject.job.api.AbstractJobProducer$JobRunner.call(AbstractJobProducer.java:273)[47:opencast-common:6.0.0.SNAPSHOT]
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_222]
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_222]
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_222]
      at java.lang.Thread.run(Thread.java:748)[:1.8.0_222]

• | DEBUG | (ServiceRegistryJpaImpl:940) - 20977 Removing from load cache: Job 35045, type org.opencastproject.composer, status FAILED
  | DEBUG | (ServiceRegistryJpaImpl:948) - 20977 Current host load: -146.80022
  | DEBUG | (ServiceRegistryJpaImpl:2652) - Try to get the services in WARNING or ERROR state triggered by this job -853662090 failed

Iam wondering where that comes from? Maybe we get that terminated by your hint to define jobloads in the encoding profile...

Thanks and best regards,

Matthias

Disclaimer - University of Cape Town This email is subject to UCT policies and email disclaimer published on our website at http://www.uct.ac.za/main/email-disclaimer or obtainable from +27 21 650 9111. If this email is not related to the business of UCT, it is sent by the sender in an individual capacity. Please report security incidents or abuse via https://csirt.uct.ac.za/page/report-an-incident.php.

[Lars Kiesow]

Hi Matthias,
just wondering, are you using an Extron SMP?
–Lars

[Matthias Vollroth]

Hi Stephen,

Thanks for your response - iam surprised, because our test cluster has the same installation with less encoding power, but has no negative loads and no encoding failures with ffmpeg status 137 - i will try to compare the config files of our test and productive system - maybe i will find something.

Hi Lars,

yes indeed - we are using SMP352 as OC capture agent - the problem occur either with uploaded files or with ingests of the SMP352.

Thanks all for your efforts and help,

Best regards,

Matthias

[Kristof Keppens]

Hi Matthias,

We’ve encountered the same ffmpeg status 137 error on our production system, but this is running on openshift ( kubernetes ). We fixed this by limiting the amount of encoding jobs on a single instance. We were thinking that it was only an issue with an openshift/kubernetes like system when enforcing certain resource quotas as we do and that it wouldn’t be an issue on regular VM’s or when we change our configuration so that we don’t enforce any resource quota’s. There isn’t anything limiting the amount of memory resources on your system and killing ffmpeg when it exceeds that limit?

Kristof

[Lars Kiesow]

Hi Matthias,

> yes indeed - we are using SMP352 as OC capture agent - the problem
> occur either with uploaded files or with ingests of the SMP352.

Then you can very likely ignore all the job load suggestions. Extron in
the past had some bugs where they produced some invalid media streams
(essentially broken files) by claiming either to have additional
unspecified data or and audio stream in those files while there was
none.

IIRC that specific behavior you see encountered with their audio bug.
What essentially happened when I investigated that was that the SMP
files claimed to have an audio and a video stream. The FFmpeg profiles
were set to process both – obviously, we don't want to drop existing
streams.

FFmpeg now started to read data but only got video data. Since it was
told to process existing audio data and the file claimed there to be
audio data, it would cache the video data and seek further to get to
the audio data. Well… since there are no actual audio data, the result
obviously was that at some point it dies since it could not cache more
video data.

For fixes:

- Either we or SWITCH (I don't remember) contacted Extron at that time
and I think they released a firmware fixing that at some point.

- For dual-stream recordings, you may be able to make sure that audio
is properly included in both streams in dome SMP settings.

- An additional quick-fix is probably to specifically drop or not
process a certain audio stream in FFmpeg if there shouldn't be one.

Sorry that I cannot give you more details. I has been a while that I
encountered that error …and of course, it could be something else
entirely ;-)

Best regards,
Lars

[Matthias Vollroth]

Hi Kristofs, thanks for your efforts.

"There isn’t anything limiting the amount of memory resources on your system and killing ffmpeg when it exceeds that limit"

No there is not - the server instance is not limited in any way - composer jobloads are on default (job.load.max.multiple.profiles=0.8 / job.load.factor.process.smil=0.5) on both clusters.

Only on the productive system ffmpeg jobs just consuming more ressources as available - then linux is automatically killing these jobs with sigkill and the encoding of 720p/1080p gets aborted.

The most unexpecting thing - the testcluster with the same installation is working fine (parallel encodings etc) and got normal host loads (positive) - there are no aborted encodings while testing both clusters simultaneously with the same video ingests (also with ingests and manually uploads of the SMP352 dual stream recordings). The productive worker shows negative host loads in the logs either with 4 cores 8 gb or with 24 cores 128gb - the testsystem do not. We gave the productive worker more ressources cause we thought that would help - but the negative host loads and ffmpeg 137 errors were still present (especially with files above 2gb and parallel encodings).

Thanks for the input and your efforts Lars, much apprecciated - all hints could help us.

Both recordings of the SMP352 are with audio - like described before we do not have this behavior on the testcluster nor with ingesting small filesizes of the SMP on the productive worker. Ive tested both clusters simultanously with exactly the same files of the smp352. I guess we can exclude the input files of the smp352 due to the testserver is working fine.

I compared nearby all config files of the test and productive cluster -  i cant find any major differences.

I will try to define job loads for the productive system and cross fingers - maybe Stephen is right and it could be a bug.

Thanks a lot for your support!

Regards,

Matthias

[Matthias Vollroth]

Additionally - maybe that helps for debugging. There are 2 encodings in the moment and Iam getting weird loads again:

 | DEBUG | (AbstractJobProducer:176) - 17314 Current load on this host: -25.600006, job's load: 0.1, job's status: QUEUED, max load: 24.0
 | DEBUG | (AbstractJobProducer:199) - 17314 Accepting job 40548 of type org.opencastproject.timelinepreviews with load 0.1 because load of -25.5 is within this node's limit of 24.
 | DEBUG | (ServiceRegistryJpaImpl:934) - 17314 Adding to load cache: Job 40548, type org.opencastproject.timelinepreviews, status RUNNING
 | DEBUG | (ServiceRegistryJpaImpl:948) - 17314 Current host load: -25.500006
 | DEBUG | (HttpsFilter:67) - Found forwarded SSL header
 | DEBUG | (AbstractPreAuthenticatedProcessingFilter:87) - Checking secure context token: null
 | DEBUG | (AbstractPreAuthenticatedProcessingFilter:108) - No pre-authenticated principal found in request
....
 | DEBUG | (HttpsFilter:67) - Found forwarded SSL header
 | DEBUG | (AbstractPreAuthenticatedProcessingFilter:87) - Checking secure context token: null
 | DEBUG | (AbstractPreAuthenticatedProcessingFilter:108) - No pre-authenticated principal found in request
 | DEBUG | (TransparentProxyFilter:59) - Found X-Forwarded-For header. Resetting source IP
 | DEBUG | (JsonpFilter:112) - No json padding requested from org.opencastproject.kernel.filter.proxy.TransparentProxyRequestWrapper@60e52ede
 | DEBUG | (AbstractJobProducer:176) - 17326 Current load on this host: -25.500006, job's load: 0.1, job's status: QUEUED, max load: 24.0
 | DEBUG | (AbstractJobProducer:199) - 17326 Accepting job 40549 of type org.opencastproject.timelinepreviews with load 0.1 because load of -25.4 is within this node's limit of 24.
 | DEBUG | (ServiceRegistryJpaImpl:934) - 17326 Adding to load cache: Job 40549, type org.opencastproject.timelinepreviews, status RUNNING
 | DEBUG | (ServiceRegistryJpaImpl:948) - 17326 Current host load: -25.400005

[Ruth Lang]

Hi Matthias,

what you are describing sounds weird.

We also have several SMP352 and many of the recorded lectures takes 4 hours. We could not see any problems with parallel encoding.

Also if ffmpeg jobs needs more resources (mainly CPU) than available (which should not be the case) no ffmpeg job was ever killed.

I am not sure if this helps:

- But have you adapted the JAVA min and max variables ? We noticed, that the default values reduce the encoding possibilities, especially for a worker VM with your parameter.

- Besides some „normal“ worker VMs we also use a “real“ GPU worker with 32 cores. For that reason we have to set job load parametersin the encoding profiles themselves. Did you try this ?

Best

Ruth

Am 25.10.2019 um 12:49 schrieb Matthias Vollroth <thd.ma...@gmail.com>:

Hi Kristofs, thanks for your efforts.

"There isn’t anything limiting the amount of memory resources on your system and killing ffmpeg when it exceeds that limit"

No there is not - the server instance is not limited in any way - composer jobloads are on default (job.load.max.multiple.profiles=0.8 / job.load.factor.process.smil=0.5) on both clusters.

Only on the productive system ffmpeg jobs just consuming more ressources as available - then linux is automatically killing these jobs with sigkill and the encoding of 720p/1080p gets aborted.

[Matthias Vollroth]

Thanks Ruth,

Not sure about Java min and max variables - i have to check that.

I will try to adjust job loads in the next step and will come back with the outcome.

Thanks all for your inputs - much appreciated!

[Matthias Vollroth]

Hi all,

the problem is solved.

Just to enlighten all who are facing the same behavior - we found out that the Engage-Node could not reach the worker node via https (Port 443 was blocked).

Thanks all for your efforts - much appreciated. 

[Dietmar Zenker]

Hi all,

after adding a new worker two weeks ago, I was confronted with the same problem: on heavy load, the worker ran out of memory completely and the system killed ffmpeg threads which resulted in failing workflows. By accident, I found this thread and Matthias' advice, and indeed: enabling a connection between the engage and worker node has solved this problem!

Though I don't understand why an engage node has to communicate with a worker node (can anybody explain this?), IMO this should be pointed out in the documentation to avoid others to stumble into the same pitfall.

Greetings,

Dietmar

[Greg Logan]

Hi Dietmar,

That's probably a bug. I can see (maybe) a situation where presentation would need to talk to admin, but it should not need to talk to the worker. Any idea which operation(s) are causing this? 

G

--

[Dietmar Zenker]

Hi Greg,

there are countless warning messages in the engage node log similar to these:

2020-04-19T07:05:11,428 | WARN  | (ServiceRegistryJpaImpl$JobProducerHeartbeat:3405) - Added org.opencastproject.caption@http://worker.myopencast.de to the watch list
2020-04-19T07:06:11,446 | WARN  | (ServiceRegistryJpaImpl$JobProducerHeartbeat:3394) - Unable to reach org.opencastproject.composer@http://worker.myopencast.de : {}
org.opencastproject.security.api.TrustedHttpClientException: org.apache.http.conn.ConnectTimeoutException: Connect to worker.myopencast.de:80 timed out
        at org.opencastproject.kernel.security.TrustedHttpClientImpl.execute(TrustedHttpClientImpl.java:394) ~[?:?]
        at org.opencastproject.kernel.security.TrustedHttpClientImpl.execute(TrustedHttpClientImpl.java:346) ~[?:?]
        at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobProducerHeartbeat.run(ServiceRegistryJpaImpl.java:3366) [91:opencast-serviceregistry:7.6.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.apache.http.conn.ConnectTimeoutException: Connect to worker.myopencast.de:80 timed out
        at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:123) ~[?:?]
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) ~[?:?]
        at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:326) ~[?:?]
        at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:605) ~[?:?]
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:440) ~[?:?]
        at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:835) ~[?:?]
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) ~[?:?]
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108) ~[?:?]
        at org.opencastproject.kernel.http.impl.HttpClientImpl.execute(HttpClientImpl.java:77) ~[?:?]
        at org.opencastproject.kernel.security.TrustedHttpClientImpl.execute(TrustedHttpClientImpl.java:387) ~[?:?]
        ... 9 more
2020-04-19T07:06:11,447 | INFO  | (ServiceRegistryJpaImpl:1475) - Unregistering Service org.opencastproject.composer@http://worker.myopencast.de and cleaning its running jobs
2020-04-19T07:06:11,521 | WARN  | (ServiceRegistryJpaImpl$JobProducerHeartbeat:3402) - Marking org.opencastproject.composer@http://worker.myopencast.de as offline
2020-04-19T07:07:11,563 | WARN  | (ServiceRegistryJpaImpl$JobProducerHeartbeat:3394) - Unable to reach org.opencastproject.coverimage@http://worker.myopencast.de : {}
org.opencastproject.security.api.TrustedHttpClientException: org.apache.http.conn.ConnectTimeoutException: Connect to worker.myopencast.de:80 timed out
        at org.opencastproject.kernel.security.TrustedHttpClientImpl.execute(TrustedHttpClientImpl.java:394) ~[?:?]
        at org.opencastproject.kernel.security.TrustedHttpClientImpl.execute(TrustedHttpClientImpl.java:346) ~[?:?]
        at org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl$JobProducerHeartbeat.run(ServiceRegistryJpaImpl.java:3366) [91:opencast-serviceregistry:7.6.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.apache.http.conn.ConnectTimeoutException: Connect to worker.myopencast.de:80 timed out
        at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:123) ~[?:?]

The dispatchinterval is set to 0 in org.opencastproject.serviceregistry.impl.ServiceRegistryJpaImpl.cfg of the engage and worker node. But, should the heartbeat.interval be set to 0, too? At the moment this is commented out and the default (60 s) is effective, but in the docu it is not described that this has to be changed, thus I didn't touch this.

Greetings,

Dietmar

[Greg Logan]

Hi Dietmar,

It's funny how different environments expose assumptions in our code :)  The heartbeat checks to see if a service's dispatch endpoint is up and returning valid data, which is a fine thing to do from all nodes.  Except your environment has the workers inaccessible from (presumably) a non-admin node, which is what's causing the errors - every node is checking every *other* node all the time.  This doesn't cause any issues as long as all nodes can reach all other nodes, but does it there are some nodes unreachable.

Here's the fun part: Since the admin node is the *only* one doing the dispatching, the *only* node whose heartbeat checks matter is the admin node.  In fact, introducing heartbeats from presentation could cause slowdowns because worker nodes could get marked as offline since they *are* offline from the presentation node's point of view.

In short: IMO the docs are missing a section about setting that to zero on non-admin nodes.  Thanks for the bug report!

G