Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timelapse rendering goes over 100% #4153

Closed
2 of 4 tasks
eduszesz opened this issue Jun 1, 2021 · 22 comments
Closed
2 of 4 tasks

Timelapse rendering goes over 100% #4153

eduszesz opened this issue Jun 1, 2021 · 22 comments
Labels
bug Issue describes a bug done Done but not yet released unreproduced No reproduction in a dev setting yet, further analysis blocked by that
Milestone

Comments

@eduszesz
Copy link

eduszesz commented Jun 1, 2021

The problem

I'm using Octoprint through Octopi in a raspberry pi 3B. I'm using an old smartphone as a webcam to stream video and to capture time-lapses with the standard Octoprint feature.
After the print job is completed, the time-lapse rendering process goes over 100% (103%, 111%, 230%, for example), and most of the times it actually does not finish and the Rpi freezes.

Did the issue persist even in safe mode?

Yes, it did persist

If you could not test in safe mode, please state why

No response

Version of OctoPrint

1.6.1

Operating system running OctoPrint

OctoPi 0.18

Printer model & used firmware incl. version

reprap i3; marlin 1.1.9

Browser and version of browser, operating system running browser

Chrome 91.0.4472.77

Checklist of files to include below

  • Systeminfo Bundle (always include!)
  • Contents of the JavaScript browser console (always include in cases of issues with the user interface)
  • Screenshots and/or videos showing the problem (always include in case of issues with the user interface)
  • GCODE file with which to reproduce (always include in case of issues with GCODE analysis or printing behaviour)

Additional information & file uploads

timelapse rendering over 100%_1
octoprint-systeminfo-20210531205603.zip

@github-actions github-actions bot added the triage This issue needs triage label Jun 1, 2021
@foosel
Copy link
Member

foosel commented Jun 8, 2021

This is most likely an issue with the output the ffmpeg binary produces.

I'll need some information from you in order to (hopefully) proceed here. First of all, SSH into your OctoPi instance. Then run the following commands and share the output here:

  • ~/oprint/bin/octoprint config get webcam.ffmpeg
  • ~/oprint/bin/octoprint config get webcam.ffmpegCommandline
  • which ffmpeg
  • ffmpeg -version

For reference, this is what should be returned on OctoPi 0.18.0 (which according to your system info bundle you have):

$ ~/oprint/bin/octoprint config get webcam.ffmpeg
'/usr/bin/ffmpeg'
$ ~/oprint/bin/octoprint config get webcam.ffmpegCommandline
('{ffmpeg} -r {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b '
 '{bitrate} -f {containerformat} -y {filters} "{output}"')
$ which ffmpeg
/usr/bin/ffmpeg
$ ffmpeg -version
ffmpeg version 4.1.6-1~deb10u1+rpt1 Copyright (c) 2000-2020 the FFmpeg developers
built with gcc 8 (Raspbian 8.3.0-6+rpi1)
configuration: --prefix=/usr --extra-version='1~deb10u1+rpt1' --toolchain=hardened --incdir=/usr/include/arm-linux-gnueabihf --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-omx-rpi --enable-mmal --enable-neon --enable-rpi --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared --libdir=/usr/lib/arm-linux-gnueabihf --cpu=arm1176jzf-s --arch=arm
libavutil      56. 22.100 / 56. 22.100
libavcodec     58. 35.100 / 58. 35.100
libavformat    58. 20.100 / 58. 20.100
libavdevice    58.  5.100 / 58.  5.100
libavfilter     7. 40.101 /  7. 40.101
libavresample   4.  0.  0 /  4.  0.  0
libswscale      5.  3.100 /  5.  3.100
libswresample   3.  3.100 /  3.  3.100
libpostproc    55.  3.100 / 55.  3.100

Also please set the logger octoprint.timelapse to DEBUG in Settings > Logging, reproduce the problem and provide the log from that. You might have to start a print with enabled timelapse first before this logger gets listed, it's fine to set it to DEBUG while a print is ongoing as long as it's set correctly after the print ends and the rendering starts. If you don't want to waste filament in the whole process, enable & connect to the built-in virtual printer and print a short file with enabled timelapse on that.

@foosel foosel added the needs information More information is needed to further process this issue or PR label Jun 8, 2021
@cp2004 cp2004 removed the triage This issue needs triage label Jun 8, 2021
@eduszesz
Copy link
Author

eduszesz commented Jun 9, 2021

Hi!
Thanks for the help. Please find below the ffmpeg information

~/oprint/bin/octoprint config get webcam.ffmpeg
'/usr/bin/ffmpeg'

~/oprint/bin/octoprint config get webcam.ffmpegCommandline
 ('{ffmpeg} -r {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b '
 '{bitrate} -f {containerformat} -y {filters} "{output}"')

which ffmpeg
/usr/bin/ffmpeg

ffmpeg version 4.1.6-1~deb10u1+rpt1 Copyright (c) 2000-2020 the FFmpeg developers
built with gcc 8 (Raspbian 8.3.0-6+rpi1)
configuration: --prefix=/usr --extra-version='1~deb10u1+rpt1' --toolchain=hardened --incdir=/usr/include/arm-linux-gnueabihf --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-omx-rpi --enable-mmal --enable-neon --enable-rpi --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared --libdir=/usr/lib/arm-linux-gnueabihf --cpu=arm1176jzf-s --arch=arm
libavutil      56. 22.100 / 56. 22.100
libavcodec     58. 35.100 / 58. 35.100
libavformat    58. 20.100 / 58. 20.100
libavdevice    58.  5.100 / 58.  5.100
libavfilter     7. 40.101 /  7. 40.101
libavresample   4.  0.  0 /  4.  0.  0
libswscale      5.  3.100 /  5.  3.100
libswresample   3.  3.100 /  3.  3.100
libpostproc    55.  3.100 / 55.  3.100

@eduszesz
Copy link
Author

eduszesz commented Jun 9, 2021

Regarding the debug logging, I will provide it as soon as possible

@eduszesz
Copy link
Author

octoprint (1).log
Hello,
here is the log

@foosel
Copy link
Member

foosel commented Jun 14, 2021

I have the exact same versions and cannot reproduce.

@foosel foosel added bug Issue describes a bug unreproduced No reproduction in a dev setting yet, further analysis blocked by that and removed needs information More information is needed to further process this issue or PR labels Jun 14, 2021
@DAveShillito
Copy link

To give you more data, I too have seen the same thing.

I'm running a very under powered Raspberry Pi v1 256mb, and I stupidly changed the camera settings to record at HD resolution to give me a better image for monitoring, forgetting this would also mean the timelaspe was also HD, so the video render took over 3 days (lesson learned) .
So I would have chalked the 158% up to this, but since I noticed this bug from @eduszesz I thought I would add my info in case it helps.

Octoprint158pctTinelapse

The results of the commands for me

pi@octobraincr10:~ $ ~/oprint/bin/octoprint config get webcam.ffmpeg
'/usr/bin/ffmpeg'
pi@octobraincr10:~ $ ~/oprint/bin/octoprint config get webcam.ffmpegCommandline
('{ffmpeg} -r {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b '
 '{bitrate} -f {containerformat} -y {filters} "{output}"')
pi@octobraincr10:~ $ which ffmpeg
/usr/bin/ffmpeg
pi@octobraincr10:~ $ ffmpeg -version
ffmpeg version 4.1.4-1+rpt1~deb10u1 Copyright (c) 2000-2019 the FFmpeg developers
built with gcc 8 (Raspbian 8.3.0-6+rpi1)
configuration: --prefix=/usr --extra-version='1+rpt1~deb10u1' --toolchain=hardened --libdir=/usr/lib/arm-linux-gnueabihf --incdir=/usr/include/arm-linux-gnueabihf --arch=arm --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-omx-rpi --enable-mmal --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared
libavutil      56. 22.100 / 56. 22.100
libavcodec     58. 35.100 / 58. 35.100
libavformat    58. 20.100 / 58. 20.100
libavdevice    58.  5.100 / 58.  5.100
libavfilter     7. 40.101 /  7. 40.101
libavresample   4.  0.  0 /  4.  0.  0
libswscale      5.  3.100 /  5.  3.100
libswresample   3.  3.100 /  3.  3.100
libpostproc    55.  3.100 / 55.  3.100
pi@octobraincr10:~ $

My octoprint,log is
octoprint.log

I have set the timelapse debug logger and will try to get you the logs when I next print something.

@DAveShillito
Copy link

Interestingly... I have just noticed that my above image taken whilst rendering (and shortly before it finally finished) showed the file size as 820.1Mb, and when the file completed it is seen here as 500.3Mb
TimelapseIssue2
Which is about the same order of magnitude as the discrepancy (820.1/500.3 = 164%) and the first image was taken shortly (a few hours) before the render finished, so I don't know how high it finally reached.

@jollino
Copy link

jollino commented Aug 15, 2021

Hi all, same issue with OctoPrint .1.6.1 on OctoPi 0.17.0 (I haven't done a full upgrade from scratch). In my case it goes well over 160%, but I'm not sure of the final value.
The camera is a Logitech C270 and the only line in octopi.txt is camera_usb_options="-r 1280x720 -f 25".

ffmpeg config as requested:

pi@octopi:~ $ ~/oprint/bin/octoprint config get webcam.ffmpeg
'/usr/bin/ffmpeg'

pi@octopi:~ $ ~/oprint/bin/octoprint config get webcam.ffmpegCommandline
u'{ffmpeg} -r {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b {bitrate} -f {containerformat} -y {filters} "{output}"'

pi@octopi:~ $ which ffmpeg
/usr/bin/ffmpeg

pi@octopi:~ $ ffmpeg -version
ffmpeg version 4.1.6-1~deb10u1+rpt1 Copyright (c) 2000-2020 the FFmpeg developers
built with gcc 8 (Raspbian 8.3.0-6+rpi1)
configuration: --prefix=/usr --extra-version='1~deb10u1+rpt1' --toolchain=hardened --incdir=/usr/include/arm-linux-gnueabihf --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-omx-rpi --enable-mmal --enable-neon --enable-rpi --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared --libdir=/usr/lib/arm-linux-gnueabihf --cpu=arm1176jzf-s --arch=arm
libavutil      56. 22.100 / 56. 22.100
libavcodec     58. 35.100 / 58. 35.100
libavformat    58. 20.100 / 58. 20.100
libavdevice    58.  5.100 / 58.  5.100
libavfilter     7. 40.101 /  7. 40.101
libavresample   4.  0.  0 /  4.  0.  0
libswscale      5.  3.100 /  5.  3.100
libswresample   3.  3.100 /  3.  3.100
libpostproc    55.  3.100 / 55.  3.100

pi@octopi:~ $ uname -a
Linux octopi 5.10.11-v7+ #1399 SMP Thu Jan 28 12:06:05 GMT 2021 armv7l GNU/Linux

I'll add a full log as soon as I have it.

@kennethjiang
Copy link

Tried it with ffmpeg version 4.1.6-1~deb10u1+rpt1 and a timelapse of 100k+ frames that took 5 hours to render but couldn't reproduce it.

@foosel I'm wondering if we can change to using frame counts, instead of the durations, in https://github.com/OctoPrint/OctoPrint/blob/master/src/octoprint/timelapse.py#L1096 . But take it with a grain of salt since I can't reproduce the problem.

@jneilliii
Copy link
Contributor

Recently had discussion on Discord about this. Seems @The-EG was also having it and was collecting data to see if he can easily reproduce.

@The-EG
Copy link
Contributor

The-EG commented Aug 19, 2021

My guess is that this is happening because ffmpeg is estimating a duration that does not match the actual movie duration when the output FPS is not 25FPS.

I saved a set of snapshots out and manually ran ffmpeg to produce the timelapse using the same arguments that OctoPrint would use: ffmpeg_stderr.txt

Here it says it will be 4 seconds long:

Input #0, image2, from 'temp/Calibration cube-PLA-0.4_20210819122031-%d.jpg':
   Duration: 00:00:04.00, start: 0.000000, bitrate: N/A
     Stream #0:0: Video: mjpeg, yuvj420p(pc, bt470bg/unknown/unknown), 1296x972, 25 fps, 25 tbr, 25 tbn, 25 tbc

This timelapse had 100 snapshots, and at 25fps that would be correct. But, I didn't choose 25fps, I used 15fps instead, which it does recognize for the output and would be 6 seconds:

 Output #0, mp4, to 'test.mp4':
   Metadata:
     encoder         : Lavf58.20.100
     Stream #0:0: Video: h264 (libx264) (avc1 / 0x31637661), yuvj420p(pc), 1296x972, q=-1--1, 10000 kb/s, 15 fps, 15360 tbn, 15 tbc
     Metadata:
       encoder         : Lavc58.35.100 libx264
     Side data:
       cpb: bitrate max/min/avg: 0/0/10000000 buffer size: 0 vbv_delay: -1

The time reported during encoding is quite odd...it seems to work up to 4 seconds and then jump to over 6, meaning the final render percentage shown would have been about 161%:

frame=   23 fps=0.0 q=0.0 size=       0kB time=00:00:00.00 bitrate=N/A speed=   0x    
frame=   43 fps= 14 q=15.0 size=     256kB time=-00:00:00.06 bitrate=N/A speed=N/A    
frame=   44 fps= 12 q=15.0 size=     256kB time=00:00:00.00 bitrate=32269784.6kbits/s speed=1.8e-05x    
frame=   45 fps= 11 q=15.0 size=     256kB time=00:00:00.06 bitrate=31432.2kbits/s speed=0.0157x    
frame=   46 fps=9.4 q=15.0 size=     512kB time=00:00:00.13 bitrate=31444.9kbits/s speed=0.0273x    
frame=   47 fps=8.4 q=16.0 size=     512kB time=00:00:00.20 bitrate=20966.6kbits/s speed=0.0356x    
frame=   48 fps=7.1 q=16.0 size=     768kB time=00:00:00.26 bitrate=23588.6kbits/s speed=0.0394x    
frame=   49 fps=6.5 q=16.0 size=     768kB time=00:00:00.33 bitrate=18871.9kbits/s speed=0.0441x    
frame=   50 fps=6.1 q=17.0 size=     768kB time=00:00:00.40 bitrate=15727.0kbits/s speed=0.0484x    
frame=   51 fps=5.6 q=17.0 size=    1024kB time=00:00:00.46 bitrate=17973.9kbits/s speed=0.0509x    
frame=   52 fps=5.2 q=17.0 size=    1024kB time=00:00:00.53 bitrate=15727.5kbits/s speed=0.0536x    
frame=   53 fps=5.0 q=18.0 size=    1024kB time=00:00:00.60 bitrate=13980.1kbits/s speed=0.0564x    
frame=   54 fps=4.6 q=17.0 size=    1280kB time=00:00:00.66 bitrate=15727.7kbits/s speed=0.0574x    
frame=   55 fps=4.4 q=17.0 size=    1280kB time=00:00:00.73 bitrate=14298.0kbits/s speed=0.0585x    
frame=   56 fps=4.2 q=18.0 size=    1536kB time=00:00:00.80 bitrate=15727.8kbits/s speed=0.0601x    
frame=   57 fps=4.1 q=19.0 size=    1536kB time=00:00:00.86 bitrate=14518.1kbits/s speed=0.0618x    
frame=   58 fps=3.9 q=18.0 size=    1536kB time=00:00:00.93 bitrate=13481.2kbits/s speed=0.0623x    
frame=   59 fps=3.7 q=18.0 size=    1792kB time=00:00:01.00 bitrate=14679.5kbits/s speed=0.0627x    
frame=   60 fps=3.6 q=18.0 size=    1792kB time=00:00:01.06 bitrate=13762.1kbits/s speed=0.0638x    
frame=   61 fps=3.5 q=19.0 size=    1792kB time=00:00:01.13 bitrate=12952.6kbits/s speed=0.0648x    
frame=   62 fps=3.3 q=19.0 size=    2048kB time=00:00:01.20 bitrate=13980.6kbits/s speed=0.0647x    
frame=   63 fps=3.3 q=19.0 size=    2048kB time=00:00:01.26 bitrate=13244.8kbits/s speed=0.0653x    
frame=   64 fps=3.2 q=19.0 size=    2048kB time=00:00:01.33 bitrate=12582.6kbits/s speed=0.0663x    
frame=   65 fps=3.1 q=19.0 size=    2304kB time=00:00:01.40 bitrate=13481.3kbits/s speed=0.0672x    
frame=   66 fps=3.0 q=19.0 size=    2304kB time=00:00:01.46 bitrate=12868.6kbits/s speed=0.0673x    
frame=   67 fps=3.0 q=19.0 size=    2304kB time=00:00:01.53 bitrate=12309.1kbits/s speed=0.0678x    
frame=   68 fps=2.9 q=19.0 size=    2560kB time=00:00:01.60 bitrate=13106.9kbits/s speed=0.0686x    
frame=   69 fps=2.9 q=19.0 size=    2560kB time=00:00:01.66 bitrate=12582.6kbits/s speed=0.0693x    
frame=   70 fps=2.8 q=19.0 size=    2560kB time=00:00:01.73 bitrate=12098.7kbits/s speed=0.0692x    
frame=   71 fps=2.7 q=19.0 size=    2816kB time=00:00:01.80 bitrate=12815.7kbits/s speed=0.0696x    
frame=   72 fps=2.7 q=19.0 size=    2816kB time=00:00:01.86 bitrate=12358.0kbits/s speed=0.0703x    
frame=   73 fps=2.7 q=20.0 size=    2816kB time=00:00:01.93 bitrate=11931.9kbits/s speed=0.0709x    
frame=   74 fps=2.6 q=20.0 size=    3072kB time=00:00:02.00 bitrate=12582.7kbits/s speed=0.0709x    
frame=   75 fps=2.6 q=19.0 size=    3072kB time=00:00:02.06 bitrate=12176.8kbits/s speed=0.0712x    
frame=   76 fps=2.6 q=20.0 size=    3072kB time=00:00:02.13 bitrate=11796.3kbits/s speed=0.0717x    
frame=   77 fps=2.5 q=20.0 size=    3328kB time=00:00:02.20 bitrate=12392.1kbits/s speed=0.0723x    
frame=   78 fps=2.5 q=20.0 size=    3328kB time=00:00:02.26 bitrate=12027.6kbits/s speed=0.0722x    
frame=   79 fps=2.5 q=20.0 size=    3328kB time=00:00:02.33 bitrate=11684.0kbits/s speed=0.0724x    
frame=   80 fps=2.4 q=20.0 size=    3584kB time=00:00:02.40 bitrate=12233.2kbits/s speed=0.0728x    
frame=   81 fps=2.4 q=20.0 size=    3584kB time=00:00:02.46 bitrate=11902.6kbits/s speed=0.0732x    
frame=   82 fps=2.4 q=20.0 size=    3584kB time=00:00:02.53 bitrate=11589.4kbits/s speed=0.0731x    
frame=   83 fps=2.3 q=20.0 size=    3840kB time=00:00:02.60 bitrate=12098.8kbits/s speed=0.0733x    
frame=   84 fps=2.3 q=20.0 size=    3840kB time=00:00:02.66 bitrate=11796.3kbits/s speed=0.0737x    
frame=   85 fps=2.3 q=20.0 size=    3840kB time=00:00:02.73 bitrate=11508.6kbits/s speed=0.0741x    
frame=   86 fps=2.3 q=20.0 size=    3840kB time=00:00:02.80 bitrate=11234.6kbits/s speed=0.074x    
frame=   87 fps=2.3 q=20.0 size=    4096kB time=00:00:02.86 bitrate=11704.9kbits/s speed=0.0742x    
frame=   88 fps=2.2 q=20.0 size=    4096kB time=00:00:02.93 bitrate=11438.9kbits/s speed=0.0745x    
frame=   89 fps=2.2 q=20.0 size=    4096kB time=00:00:03.00 bitrate=11184.7kbits/s speed=0.0749x    
frame=   90 fps=2.2 q=20.0 size=    4352kB time=00:00:03.06 bitrate=11625.4kbits/s speed=0.0748x    
frame=   91 fps=2.2 q=20.0 size=    4352kB time=00:00:03.13 bitrate=11378.1kbits/s speed=0.0749x    
frame=   92 fps=2.2 q=20.0 size=    4352kB time=00:00:03.20 bitrate=11141.0kbits/s speed=0.0752x    
frame=   93 fps=2.1 q=20.0 size=    4608kB time=00:00:03.26 bitrate=11555.6kbits/s speed=0.0755x    
frame=   94 fps=2.1 q=20.0 size=    4608kB time=00:00:03.33 bitrate=11324.5kbits/s speed=0.0754x    
frame=   95 fps=2.1 q=20.0 size=    4608kB time=00:00:03.40 bitrate=11102.5kbits/s speed=0.0754x    
frame=   96 fps=2.1 q=20.0 size=    4864kB time=00:00:03.46 bitrate=11493.9kbits/s speed=0.0758x    
frame=   97 fps=2.1 q=20.0 size=    4864kB time=00:00:03.53 bitrate=11277.0kbits/s speed=0.076x    
frame=   98 fps=2.1 q=20.0 size=    4864kB time=00:00:03.60 bitrate=11068.2kbits/s speed=0.0759x    
frame=   99 fps=2.1 q=20.0 size=    4864kB time=00:00:03.66 bitrate=10867.0kbits/s speed=0.076x    
frame=  100 fps=2.0 q=20.0 size=    5120kB time=00:00:03.73 bitrate=11234.7kbits/s speed=0.0763x    
frame=  100 fps=2.0 q=20.0 size=    5120kB time=00:00:03.73 bitrate=11234.7kbits/s speed=0.0752x    
frame=  100 fps=1.2 q=19.0 Lsize=    8405kB time=00:00:06.46 bitrate=10647.8kbits/s speed=0.0798x    

edit: I also double checked the output video and it is indeed just over 6 seconds long:

taylor@printerpi:~ $ ffmpeg -i test.mp4 2>&1 | grep Duration
  Duration: 00:00:06.67, start: 0.000000, bitrate: 10327 kb/s

I think this is likely more pronounced and noticeable on much longer timelapses.

Just as a test, I reran the above but used an output fps of 25. This time, the expected duration was still 4seconds, but the actual duration was also 4 seconds so everything lines up. The last progress from encoding:

frame=  100 fps=1.4 q=24.0 Lsize=    4942kB time=00:00:03.88 bitrate=10434.3kbits/s speed=0.0554x 

@The-EG
Copy link
Contributor

The-EG commented Sep 23, 2021

I stumbled across something while looking through ffmpeg docs; I think this can be resolved by using -framerate instead of -r.

TL/DR: set the default ffmpeg command to be {ffmpeg} -framerate {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b:v {bitrate} -f {containerformat} -y {filters} "{output}"

According to the docs:

r[:stream_specifier] fps (input/output,per-stream)

Set frame rate (Hz value, fraction or abbreviation).

As an input option, ignore any timestamps stored in the file and instead generate timestamps assuming constant frame rate fps. This is not the same as the -framerate option used for some input formats like image2 or v4l2 (it used to be the same in older versions of FFmpeg). If in doubt use -framerate instead of the input option -r.

Note the last two sentences.

When I specify the framerate with -framerate instead of -r, the info that ffmpeg prints out for the input now matches that framerate and so does the expected time.

With -r 15:

Input #0, image2, from 'temp/Calibration cube-PLA-0.4_20210819122031-%d.jpg':
  Duration: 00:00:04.00, start: 0.000000, bitrate: N/A
    Stream #0:0: Video: mjpeg, yuvj420p(pc, bt470bg/unknown/unknown), 1296x972, 25 fps, 25 tbr, 25 tbn, 25 tbc

With -framerate 15:

Input #0, image2, from 'temp/Calibration cube-PLA-0.4_20210819122031-%d.jpg':
  Duration: 00:00:06.67, start: 0.000000, bitrate: N/A
    Stream #0:0: Video: mjpeg, yuvj420p(pc, bt470bg/unknown/unknown), 1296x972, 15 fps, 15 tbr, 15 tbn, 15 tbc

@jneilliii
Copy link
Contributor

Has any of the people reporting this issue been able to test out @The-EG's suggestion of setting the ffmpeg command to the following?

{ffmpeg} -framerate {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b:v {bitrate} -f {containerformat} -y {filters} "{output}"

The-EG added a commit to The-EG/OctoPrint that referenced this issue Dec 13, 2021
In timelapse settings, use -framerate instead of -r.
This addresses OctoPrint#4153 for new installations.
The-EG added a commit to The-EG/OctoPrint that referenced this issue Dec 13, 2021
In timelapse settings, use -framerate instead of -r.
This addresses OctoPrint#4153 for new installations.
The-EG added a commit to The-EG/OctoPrint that referenced this issue Dec 13, 2021
In timelapse settings, use -framerate instead of -r.
This addresses OctoPrint#4153 for new installations.
foosel pushed a commit that referenced this issue Dec 15, 2021
In timelapse settings, use -framerate instead of -r.
This addresses #4153 for new installations.
@foosel
Copy link
Member

foosel commented Dec 15, 2021

Well, we still don't know if @The-EG 's suggestion solves the issue for affected users (Hey @jollino, @eduszesz, @DAveShillito some feedback would be lovely! 😅), but it'll now be how 1.8.0 ships thanks to @The-EG sending in PR #4344. So maybe this is fixed, but we don't know without anyone who can actually reproduce this confirming.

@foosel foosel added needs testing Testing from the community is needed done Done but not yet released labels Dec 15, 2021
@foosel foosel added this to the 1.8.0 milestone Dec 15, 2021
@jollino
Copy link

jollino commented Dec 15, 2021 via email

@eduszesz
Copy link
Author

Hi guys!
As I was unable to use the timelapse feature I stopped using it and start using The Spaghetti Detective.
Since I got your request for feedback on this issue, I did a test print. The over 100% problem did not occur, but the Rpi had difficulties in rendering the timelapse. It froze on the first attempt and on the second one it took a couple of hours to perform the job.
Now I'm using Octoprint 1.7.2. The Rpi is the same as before.
Thanks for all the effort in solving this issue.
Best regards
Eduardo Szesz

@DAveShillito
Copy link

Sorry,

I've been using my new Prusa without Octoprint for the last few months.
I just fired up Octoprint on my CR10 which is still using Version 1.7.0

I printed a calibration cube and the timelapse finished displaying at 164%
I then modified the file "/home/pi/oprint/lib/python3.7/site-packages/octoprint/settings.py"
replacing the
"ffmpegCommandline": '{ffmpeg} -r {fps}
with
"ffmpegCommandline": '{ffmpeg} -framerate {fps}
but again the timelapse finished at 164%

Was that the correct method to test the change, or do I need to compile the file or setup a complete dev environement? in which case can someone point me at instructions as to what I need to do to test the change.

@jneilliii
Copy link
Contributor

jneilliii commented Dec 21, 2021

I think the proper way to test would be to change the software update settings (gear icon in top right) to Github Commit and use maintenance for the tracked branch.

image

@cp2004
Copy link
Member

cp2004 commented Dec 21, 2021

The timelapse command is directly editable in the timelapse settings, probably under 'advanced' or similar.

@DAveShillito
Copy link

DAveShillito commented Dec 21, 2021

The timelapse command is directly editable in the timelapse settings, probably under 'advanced' or similar.

OMG I had never noticed the advanced options for the timelapse.

I shall revert my file changes and try again making the change in those advance settings.

I think the proper way to test would be to change the software update settings (gear icon in top right) to Github Commit and use maintenance for the tracked branch.

And this is very useful for me to know in the future, thanks

@DAveShillito
Copy link

I changed the timelapse advanced options to have the FFMPEG command line of

{ffmpeg} -framerate {fps} -i "{input}" -vcodec {videocodec} -threads {threads} -b:v {bitrate} -f {containerformat} -y {filters} "{output}"

Ran the same test print and this time the timelapse completed at 100%.

So it does look like, for me, that change has fixed the issue.

@foosel foosel removed the needs testing Testing from the community is needed label Jan 17, 2022
@cp2004
Copy link
Member

cp2004 commented May 17, 2022

1.8.0 has been released 🎉

@cp2004 cp2004 closed this as completed May 17, 2022
@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 18, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Issue describes a bug done Done but not yet released unreproduced No reproduction in a dev setting yet, further analysis blocked by that
Projects
None yet
Development

No branches or pull requests

8 participants