ffmpeg tests time out

[vbraun]

sage: a.show(iterations=3)    # optional -- ImageMagick ## line 781 ##
sage: a.show(delay=50)        # optional -- ImageMagick ## line 785 ##
sage: a.show(format="ogg")         # optional -- ffmpeg ## line 789 ##
sage: a.show(format="webm")        # optional -- ffmpeg ## line 790 ##
sage: a.show(format="mp4")         # optional -- ffmpeg ## line 791 ##
------------------------------------------------------------------------
/var/lib/buildbot/slave/sage_git/build/local/var/lib/sage/venv-python3.9.9/lib/python3.9/site-packages/cysignals/signals.cpython-39-x86_64-linux-gnu.so(+0x6c68)[0x7f3cd264cc68]
/var/lib/buildbot/slave/sage_git/build/local/var/lib/sage/venv-python3.9.9/lib/python3.9/site-packages/cysignals/signals.cpython-39-x86_64-linux-gnu.so(+0x6e48)[0x7f3cd264ce48]
/var/lib/buildbot/slave/sage_git/build/local/var/lib/sage/venv-python3.9.9/lib/python3.9/site-packages/cysignals/signals.cpython-39-x86_64-linux-gnu.so(+0x94ba)[0x7f3cd264f4ba]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f3cda990390]
/lib/x86_64-linux-gnu/libpthread.so.0(waitpid+0x6b)[0x7f3cda98ff7b]
[...]
----------------------------------------------------------------------
sage -t --long --random-seed=192258908271772461060599147744190497953 src/sage/plot/animate.py  # Timed out
----------------------------------------------------------------------

These tests were originally included in SageMath 11 years ago in #11170.

Depends on #33092

CC: @dimpase @slel @kiwifb @kwankyu @seblabbe @videlec @orlitzky

Component: graphics

Author: Sébastien Labbé

Branch/Commit: 8bb3a23

Reviewer: Matthias Koeppe

Issue created by migration from https://trac.sagemath.org/ticket/33045

[orlitzky]

comment:2

These are pretty faily on Gentoo, too, where the system ffmpeg is often built without support for (say) ogg files. I think the spkg-configure.m4 for ffmpeg should check for any features needed by an #optional - ffmpeg test.

[orlitzky]

comment:3

I've opened #33092 for the missing spkg-configure feature checks, since that's a different issue and affects imagemagick too.

[seblabbe]

comment:4

I would like to help here, but it works for me. Also, the place where it seems to block in the description of the ticket (line 791) is not mentionned in the list given by --warn-long, see below.

$ sage -t --warn-long --long src/sage/plot/animate.py 
Running doctests with ID 2021-12-29-21-42-04-97846833.
Git branch: develop
Using --optional=4ti2,bliss,build,cbc,ccache,cryptominisat,database_symbolic_data,debian,debugpy,dochtml,dot2tex,e_antic,fricas,glucose,latte_int,lidia,lrslib,normaliz,notedown,pandoc_attributes,pip,pycosat,pynormaliz,rst2ipynb,rubiks,sage,sage_numerical_backends_coin,sage_spkg
Features to be detected: 4ti2,benzene,bliss,buckygen,conway_polynomials,csdp,database_cremona_ellcurve,database_cremona_mini_ellcurve,database_jones_numfield,database_knotinfo,dvipng,ffmpeg,graphviz,imagemagick,jupymake,kenzo,latte_int,lrslib,mcqd,meataxe,pandoc,pdf2svg,plantri,pynormaliz,rubiks,sage.combinat,sage.geometry.polyhedron,sage.graphs,sage.plot,sage.rings.number_field,sage.rings.real_double,sage.symbolic,sage_numerical_backends_coin,tdlib
Doctesting 1 file.
sage -t --long --warn-long --random-seed=72502732894215646185918481252462424659 src/sage/plot/animate.py
**********************************************************************
File "src/sage/plot/animate.py", line 35, in sage.plot.animate
Warning, slow doctest:
    a         # optional -- ImageMagick
Test ran for 1.31 s
**********************************************************************
File "src/sage/plot/animate.py", line 53, in sage.plot.animate
Warning, slow doctest:
    E.show()  # optional -- ImageMagick
Test ran for 4.75 s
**********************************************************************
File "src/sage/plot/animate.py", line 59, in sage.plot.animate
Warning, slow doctest:
    c.show() # optional -- ImageMagick
Test ran for 1.86 s
**********************************************************************
File "src/sage/plot/animate.py", line 69, in sage.plot.animate
Warning, slow doctest:
    sp[0]      # first frame
Test ran for 1.00 s
**********************************************************************
File "src/sage/plot/animate.py", line 73, in sage.plot.animate
Warning, slow doctest:
    sp.show()  # optional -- ImageMagick
Test ran for 6.51 s
**********************************************************************
File "src/sage/plot/animate.py", line 79, in sage.plot.animate
Warning, slow doctest:
    a[0]       # long time
Test ran for 1.64 s
**********************************************************************
File "src/sage/plot/animate.py", line 81, in sage.plot.animate
Warning, slow doctest:
    a.show()   # optional -- ImageMagick
Test ran for 14.16 s
**********************************************************************
File "src/sage/plot/animate.py", line 90, in sage.plot.animate
Warning, slow doctest:
    a.show()  # optional -- ImageMagick
Test ran for 1.61 s
**********************************************************************
File "src/sage/plot/animate.py", line 138, in sage.plot.animate.animate
Warning, slow doctest:
    a.show()  # optional -- ImageMagick
Test ran for 1.57 s
**********************************************************************
File "src/sage/plot/animate.py", line 166, in sage.plot.animate.Animation
Warning, slow doctest:
    a                 # optional -- ImageMagick
Test ran for 4.44 s
**********************************************************************
File "src/sage/plot/animate.py", line 168, in sage.plot.animate.Animation
Warning, slow doctest:
    a[:5]             # optional -- ImageMagick
Test ran for 1.17 s
**********************************************************************
File "src/sage/plot/animate.py", line 170, in sage.plot.animate.Animation
Warning, slow doctest:
    a.show()          # optional -- ImageMagick
Test ran for 1.08 s
**********************************************************************
File "src/sage/plot/animate.py", line 171, in sage.plot.animate.Animation
Warning, slow doctest:
    a[:5].show()      # optional -- ImageMagick
Test ran for 1.06 s
**********************************************************************
File "src/sage/plot/animate.py", line 179, in sage.plot.animate.Animation
Warning, slow doctest:
    a.show(delay=50, iterations=4) # optional -- ImageMagick
Test ran for 1.09 s
**********************************************************************
File "src/sage/plot/animate.py", line 190, in sage.plot.animate.Animation
Warning, slow doctest:
    a.show() # optional -- ImageMagick
Test ran for 2.81 s
**********************************************************************
File "src/sage/plot/animate.py", line 205, in sage.plot.animate.Animation
Warning, slow doctest:
    a.show() # optional -- ImageMagick
Test ran for 5.40 s
**********************************************************************
File "src/sage/plot/animate.py", line 213, in sage.plot.animate.Animation
Warning, slow doctest:
    a.png()    # long time
Test ran for 1.64 s
**********************************************************************
File "src/sage/plot/animate.py", line 234, in sage.plot.animate.Animation.__init__
Warning, slow doctest:
    a           # optional -- ImageMagick
Test ran for 4.45 s
**********************************************************************
File "src/sage/plot/animate.py", line 282, in sage.plot.animate.Animation.__getitem__
Warning, slow doctest:
    a           # optional -- ImageMagick
Test ran for 1.97 s
**********************************************************************
File "src/sage/plot/animate.py", line 304, in sage.plot.animate.Animation._repr_
Warning, slow doctest:
    a           # optional -- ImageMagick
Test ran for 2.03 s
**********************************************************************
File "src/sage/plot/animate.py", line 560, in sage.plot.animate.Animation.?
Warning, slow doctest:
    a.gif(savefile=td + 'my_animation.gif', delay=35, iterations=3)  # optional -- ImageMagick
Test ran for 1.96 s
**********************************************************************
File "src/sage/plot/animate.py", line 635, in sage.plot.animate.Animation.?
Warning, slow doctest:
    a._gif_from_imagemagick(savefile=td + 'new.gif') # optional -- imagemagick
Test ran for 1.88 s
**********************************************************************
File "src/sage/plot/animate.py", line 685, in sage.plot.animate.Animation._rich_repr_
Warning, slow doctest:
    a._rich_repr_(dm)       # optional -- ImageMagick
Test ran for 1.20 s
**********************************************************************
File "src/sage/plot/animate.py", line 776, in sage.plot.animate.Animation.show
Warning, slow doctest:
    a.show()       # optional -- ImageMagick
Test ran for 1.90 s
**********************************************************************
File "src/sage/plot/animate.py", line 889, in sage.plot.animate.Animation.?
Warning, slow doctest:
    a.ffmpeg(savefile=td + 'new.mpg')       # optional -- ffmpeg
Test ran for 1.58 s
**********************************************************************
File "src/sage/plot/animate.py", line 1005, in sage.plot.animate.Animation.apng
Warning, slow doctest:
    a.apng()  # long time
Test ran for 1.42 s
**********************************************************************
File "src/sage/plot/animate.py", line 1067, in sage.plot.animate.Animation.save
Warning, slow doctest:
    a.save(td + 'wave.gif')   # optional -- ImageMagick
Test ran for 1.98 s
**********************************************************************
File "src/sage/plot/animate.py", line 1219, in sage.plot.animate.APngAssembler
Warning, slow doctest:
    assembleAPNG()  # long time
Test ran for 1.42 s
    [243 tests, 93.59 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 93.7 seconds
    cpu time: 50.9 seconds
    cumulative wall time: 93.6 seconds
Features detected for doctesting: ffmpeg,imagemagick
Pytest is not installed, skip checking tests that rely on it.

We can see that there is a bunch of long tests which are not marked as long, but this should not change anything.

Maybe we can change few very long tests (>10s) as not tested. Since, it works on my machine, it is difficult to propose a branch that fixes the issue. However, I can act as a reviewer here.

[seblabbe]

comment:6

These tests were originally included 11 years ago in #11170. A follow-up ticket #11650 changed the default back to convert because the gif generated by ffmpeg were very large.

[seblabbe]

comment:7

I am adding #33092 here as a dependency, because after #33092 (which I hope will make it to 9.5?) the feature ffmpeg is now doctested only if it is functional, which may have an impact on the issue reported here.

[seblabbe]

Dependencies: #33092

[seblabbe]

comment:8

@orlitzky: you said you were able to reproduce the time out for this file after the application of #33092 ? If yes, could you post here the output of

sage -t --warn-long --long src/sage/plot/animate.py 

just so that we have a clearer idea of which tests are long. In my case, almost none of the ffmpeg tests are warned to be long (see #33045 comment:4).

[orlitzky]

comment:9

Replying to @seblabbe:

@orlitzky: you said you were able to reproduce the time out for this file after the application of #33092

I think my timeout problem is different. In my case, without --long, the file overruns the default (non-long) timeout of five minutes. But when --long is used (as it is in Volker's report), the timeout gets set to thirty minutes. That's plenty of time. So to me it sounds like his ffmpeg is getting hung. Maybe we need -nostdin on the ffmpeg commands?

[seblabbe]

comment:10

Ok, here a branch doing that. Maybe that fixes the issue for the machine having the problem. @Volker?

---

New commits:

8bb3a23

33045: adding -nostdin argument to ffmpeg command

[seblabbe]

Branch: public/33045

[seblabbe]

Commit: 8bb3a23

[seblabbe]

Author: Sébastien Labbé

[seblabbe]

comment:11

Bonjour,

As I mentionned earlier in this ticket, the machine I have access to do not observe the time out failure observed by Volker on the buildbot with respect to ffmpeg doctests. The branch I posted here is a possible fix (it was the solution to a similar hang which was observed in #33092), but I can't confirm. This is a situation where it would be nice for author/reviewer here to reproduce the issue and test whether it works on the buildbot without asking Volker himself to do it. Otherwise, the only solution is that Volker becomes a reviewer of this ticket, but I don't want to use Volker as a CI to reuse his own expression.

Is there a way, maybe using tox (?) to reproduce the issue seen on the build bot with respect to ffmpeg?

Sincerely,

Sébastien

[slel]

comment:12

Set milestone to sage-9.6 after Sage 9.5 release.

[mkoeppe]

comment:13

I have not seen the reported failures in environments provisioned using tox, as for example the automatic runs on GH Actions... because ffmpeg is not installed by either the -minimal and -standard configurations.

We can't guess what packages may be installed on the machine where the reported failures occurred.

In any case the fix looks reasonable to me and here on macOS with homebrew, ./sage -t --optional=sage,optional,external src/sage/plot/animate.py gives

sage -t --random-seed=278059732320647035924475847071326670064 src/sage/plot/animate.py
    [231 tests, 126.60 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 131.5 seconds
    cpu time: 67.1 seconds
    cumulative wall time: 126.6 seconds
Features detected for doctesting: ffmpeg,imagemagick

[mkoeppe]

Reviewer: Matthias Koeppe

[vbraun]

Changed branch from public/33045 to 8bb3a23