Switch to channel is significantly delayed (Liquidsoap 2.1)
When switching from fallback source to a mixer channel (e.g. input queue), the actual play-out of the channel takes around 23 seconds.
This is not related to any pre-loading, as there is plenty of preceeding time to get any buffers filled.
- Liquidsoap 2.1 (deb)
- Test case: engine-core/tests$ liquidsoap test_queue_activate.liq
Logs
The log is indicating that the track started playing at 13:58:59 but music was audible only 23 seconds later.
Fallback playing
2022/08/02 13:58:54 >>> LOG START
2022/08/02 13:58:53 [main:3] Liquidsoap 2.1.0
2022/08/02 13:58:53 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] posix-time2=2.0.0 pcre=7.5.0 sedlex=3.0 menhirLib=20220210 curl=0.9.2 memtrace=v0.2.2 mem_usage=0.0.4 dtools=0.4.4 duppy=0.9.2 cry=0.6.8 mm=0.8.1 xmlplaylist=0.1.5 lastfm=0.3.3 ogg=0.7.2 ogg.decoder=0.7.2 vorbis=0.8.1 vorbis.decoder=0.8.1 opus=0.2.2 opus.decoder=0.2.2 speex=0.4.1 speex.decoder=0.4.1 mad=0.5.2 flac=0.3.0 flac.ogg=0.3.0 flac.decoder=0.3.0 dynlink=[distributed with Ocaml] lame=0.3.6 shine=0.2.3 frei0r=0.1.2 fdkaac=0.3.2 theora=0.4.0 theora.decoder=0.4.0 ffmpeg=1.1.4 bjack=0.1.6 alsa=0.3.0 ao=0.2.4 samplerate=0.1.6 taglib=0.3.9 ssl=0.5.9 magic=0.7.3 camomile=1.0.2 inotify=2.3 faad=0.5.2 soundtouch=0.1.9 portaudio=0.2.3 pulseaudio=0.1.5 ladspa=0.2.2 dssi=0.1.5 tsdl=v0.9.9 tsdl-ttf=0.3.2 tsdl-image=0.3.2 camlimages=4.2.6 camlimages.freetype=5.0.4 cohttp-lwt-unix=5.0.0 prometheus-app=1.2 srt.constants=0.2.2 srt.types=0.2.2 srt.stubs=0.2.2 srt.stubs.locked=0.2.2 srt=0.2.2 lo=0.2.0 gd=1.0a5
2022/08/02 13:58:53 [clock:3] Using native (high-precision) implementation for latency control
2022/08/02 13:58:54 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2022/08/02 13:58:54 [frame:3] Video frame size set to: 1280x720
2022/08/02 13:58:54 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2022/08/02 13:58:54 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2022/08/02 13:58:54 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2022/08/02 13:58:54 [sandbox:3] Sandboxing disabled
2022/08/02 13:58:54 [video.converter:3] Using preferred video converter: ffmpeg.
2022/08/02 13:58:54 [audio.converter:3] Using samplerate converter: libsamplerate.
2022/08/02 13:58:54 [video.text:3] Using camlimages implementation
2022/08/02 13:58:54 [clock.alsa:3] Streaming loop starts in auto-sync mode
2022/08/02 13:58:54 [clock.alsa:3] Delegating synchronisation to CPU clock
2022/08/02 13:58:54 [mksafe:3] Switch to switch_2.
2022/08/02 13:58:54 [switch_2:3] Switch to mksafe.
2022/08/02 13:58:54 [mksafe:3] Switch to safe_blank.
2022/08/02 13:58:54 [fallback_folder:3] Prepared "../audio/fallback/The XX - XX (16bit)/08-Basic Space.flac" (RID 3).
on_track - update (TRACK: , ON AIR:
2022/08/02 13:58:54 [mksafe:3] Switch to fallback_folder with transition.
2022/08/02 13:58:54 [alsa_out(default):3] Using ALSA 1.2.4.
2022/08/02 13:58:54 [alsa_out(default):2] Falling back on interleaved S16LE
2022/08/02 13:58:54 [alsa_out(default):3] channels=2, samplerate=44100Hz, buffer size=1048576B, frame size=4B, periods=1024
on_metadata - update (TRACK: Basic Space, ON AIR: 2022/08/02 13:58:54
on_track - update (TRACK: Basic Space, ON AIR: 2022/08/02 13:58:54
2022/08/02 13:58:54 [clock.alsa:3] Delegating synchronisation to active sources
Activate queue
["ready=true selected=true single=false volume=100% remaining=inf"]
["ready=true selected=true single=false volume=100% remaining=inf"]
2022/08/02 13:58:59 [in_queue:3] Prepared "assets/audio.mp3" (RID 0).
2022/08/02 13:58:59 [switch_2:3] Switch to blank.strip_0 with transition.
2022/08/02 13:58:59 [switch_1:3] Switch to on_metadata_0.
[mp3float @ 0x7fb4d80f4d40] Could not update timestamps for skipped samples.
on_metadata - update (TRACK: Two Pianos (ft. Admiral Bob (admiralbob77)), ON AIR: 2022/08/02 13:58:59
on_track - update (TRACK: Two Pianos (ft. Admiral Bob (admiralbob77)), ON AIR: 2022/08/02 13:58:59
Edited by David Trattnig