Olive version: March 2019 | Alpha | c5f63ec
Source: https://www.olivevideoeditor.org
Operating system: MacOS High Sierra 10.13.6 (17G6030)
CPU: 2,8 GHz Intel Core i7
RAM: 16 GB 1333 MHz DDR3
GPU: Intel HD Graphics 3000 512 MB
Working with Olive, I get almost no sound during playback. When I hit play, I hear audio less than a second before it starts to crackle and eventually audio playback completely stops. I have to stop and restart playback to hear another few milliseconds of sound before it drops out again. To me, this sounds like a buffer sync error. The problem occurs with all video and audio files on all audio output devices. Changing sample rates does not make a difference. The debug log does not show any related error.
Load any file with an audio track into the timeline and hit play...
[WARNING] libpng warning: iCCP: known incorrect sRGB profile (:0, )
[INFO] Initializing custom cursors (:0, )
[INFO] Finished initializing custom cursors (:0, )
[INFO] Initializing icons (:0, )
[INFO] Finished initializing icons (:0, )
[INFO] Initializing effects... (:0, )
[INFO] Finished initializing effects (:0, )
[WARNING] libpng warning: iCCP: known incorrect sRGB profile (:0, )
[WARNING] QObject::connect: Cannot queue arguments of type 'QVector' (Make sure 'QVector' is registered using qRegisterMetaType().) (:0, )
[INFO] Clip opened on track 0 (took 9 ms) (:0, )
[INFO] Clip opened on track -1 (took 8 ms) (:0, )
[INFO] Auto-recovery project saved (:0, )
Any help is highly appreciated!
Thank you very much!
Hello! I'm confirming this bug and watching it from time to time.
I'm also having this issue :\
I appreciate that folks are reporting this, but have a look how much information is being communicated. No wrapper, no internal codec. Nothing. If folks with issues invest a bit of investigative work and diagnose precisely what the constants are, it makes potentially solving the issues feasible.
With no information, we might as well just close this report. Sound good?
Mac OS X 10.9.5
2.3 GHz Intel Core i7
(Self-compiled.)
FWIW I had taken a quick with dapptrace and (I think) dtruss while the issue was happening but nothing leapt out at me as being an obvious lead to track down--so I just subscribed to this issue rather than report "me also".
I just took another quick look and noticed a difference in audio playback behaviour when a clip was selected and the effects tab was populated--but it didn't seem consistent.
But then, weirdly, I noticed that if I left the mouse pointer over the "Project" sub-window/tab the audio played pretty much completely but if I started moving the mouse pointer in circles (and especially in circles over the main timeline) the audio drop-outs/crackles occurred frequently.
Perhaps there's an issue around event handling/audio code/threading?
I would recommend keeping this issue open but recommending that if people don't yet have new information to add that they just subscribe to the issue and/or "+1" the first comment to indicate they are also encountering the issue.
@follower is it safe to say this is all wrappers and internal codecs? I believe all sampling is still FFMPEG with no internal caching, so it would be good to ascertain if there are codec issues at play.
[Note: This very much an incomplete brain dump of data but maybe it contains some useful additional context.]
I'm not sure I 100% understand your question but if I add a "Tone" track to the project I'm testing with, the generated tone playback is also affected. [But from my additional investigation I don't think the audio sample side of things is just FFMPEG.]
Also, the crackle/dropout seems like it's primarily related to the "Effects Control" (sub-)window, if I have e.g. just the Project window open it seems like there's less issue...
dapptraceWith just the "Effects Control" window open (and a video/audio clip selected with no audio effects applied and only the Transform video effect) I ran sudo dapptrace -c -e -p <PID> and noticed a few things in the output...
This is pretty early in the run and included to give some context for relative elapsed time timings but also shows some longer elapsed time values as they occur:
ELAPSD CALL(args) = return
[...]
. -> frame_to_timecode(long, int, double)(0x7FFF5BC76850, 0x545, 0x0)
46 <- frame_to_timecode(long, int, double) = 2556
. -> frame_to_timecode(long, int, double)(0x7FFF5BC76850, 0x59F, 0x0)
52 <- frame_to_timecode(long, int, double) = 2556
. -> olive::styling::GetIconColor()(0x7FFF5BC76840, 0x8, 0xF2976C)
44 <- olive::styling::GetIconColor() = 58
. -> getScreenPointFromFrame(double, long)(0xF0, 0x8, 0x8)
54 <- getScreenPointFromFrame(double, long) = 78
3450 <- TimelineHeader::paintEvent(QPaintEvent*) = 2779
. -> Cacher::metaObject() const(0x7FCA8863F580, 0x7FCA8863F580, 0x0)
28 <- Cacher::metaObject() const = 29
. -> Cacher::run()(0x7FCA8863F580, 0x1, 0x0)
. -> Cacher::OpenWorker()(0x7FCA8863F580, 0x1, 0x1)
. -> Clip::track()(0x7FCA8863F4B8, 0x7FFFFFE00050, 0x0)
15 <- Clip::track() = 11
. -> Clip::media()(0x7FCA8863F4B8, 0x7FFFFFE00050, 0x0)
15 <- Clip::media() = 12
. -> Clip::media()(0x7FCA8863F4B8, 0x7FFFFFE00050, 0x0)
14 <- Clip::media() = 12
. -> Media::get_type()(0x6000000BA898, 0x7FFFFFE00050, 0x0)
18 <- Media::get_type() = 8
. -> Clip::media()(0x7FCA8863F4B8, 0x7FFFFFE00050, 0x0)
14 <- Clip::media() = 12
. -> Media::to_footage()(0x6000000BA898, 0x7FFFFFE00050, 0x0)
19 <- Media::to_footage() = 9
. -> Clip::media_stream()(0x7FCA8863F4B8, 0x100, 0xE8)
. -> Media::get_type()(0x6000000BA898, 0x100, 0xE8)
17 <- Media::get_type() = 8
. -> Media::to_footage()(0x6000000BA898, 0x100, 0xE8)
19 <- Media::to_footage() = 9
104 <- Clip::media_stream() = 75
. -> Footage::get_stream_from_file_index(bool, int)(0x60000032B4B8, 0x0, 0x1)
41 <- Footage::get_stream_from_file_index(bool, int) = 220
. -> ClipQueue::append(AVFrame*)(0x7FCA8863F598, 0x7FCA8865B300, 0xFFFFFFFFFFFFFFC8)
47 <- ClipQueue::append(AVFrame*) = 102
. -> current_audio_freq()(0x7FCA8864ED10, 0x0, 0xFFFFFFFFFFFFFFC8)
37 <- current_audio_freq() = 69
. -> ClipQueue::append(AVFrame*)(0x7FCA8863F598, 0x7FCA8864EB00, 0x0)
44 <- ClipQueue::append(AVFrame*) = 102
. -> Clip::IsOpen()(0x7FCA8863F6C8, 0x1, 0x7FCA88645CB4)
28 <- Clip::IsOpen() = 11
. -> Clip::track()(0x7FCA8863F6C8, 0x1, 0x7FCA88645CB4)
24 <- Clip::track() = 11
. -> Clip::media_width()(0x7FCA8863F6C8, 0x1, 0x7FCA88645CB4)
. -> Media::get_type()(0x6000000BA898, 0x1, 0x7FCA88645CB4)
31 <- Media::get_type() = 8
. -> Media::get_type()(0x6000000BA898, 0x1, 0x7FCA88645CB4)
30 <- Media::get_type() = 8
. -> Media::to_footage()(0x6000000BA898, 0x1, 0x7FCA88645CB4)
33 <- Media::to_footage() = 9
. -> Footage::get_stream_from_file_index(bool, int)(0x60000032B4B8, 0x1, 0x0)
71 <- Footage::get_stream_from_file_index(bool, int) = 220
408 <- Clip::media_width() = 190
. -> Clip::media_height()(0x7FCA8863F6C8, 0x1, 0x0)
. -> Media::get_type()(0x6000000BA898, 0x1, 0x0)
29 <- Media::get_type() = 8
. -> Media::get_type()(0x6000000BA898, 0x1, 0x0)
. -> Media::to_footage()(0x6000000BA898, 0x1, 0x0)
. -> Footage::get_stream_from_file_index(bool, int)(0x60000032B4B8, 0x1, 0x0)
69 <- Footage::get_stream_from_file_index(bool, int) = 220
330 <- Clip::media_height() = 190
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x0)
24 <- Clip::media() = 12
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x0)
25 <- Clip::media() = 12
. -> Media::get_type()(0x6000000BA898, 0x1, 0x0)
29 <- Media::get_type() = 8
. -> Clip::timeline_in(bool)(0x7FCA8863F6C8, 0x0, 0x0)
39 <- Clip::timeline_in(bool) = 62
. -> Clip::Cache(long, bool, QVector<Clip*>&, int)(0x7FCA8863F6C8, 0x0, 0x0)
. -> Cacher::Cache(long, bool, QVector<Clip*>&, int)(0x7FCA8863F790, 0x0, 0x0)
. -> Clip::media_stream()(0x7FCA8863F6C8, 0x0, 0x0)
. -> Media::get_type()(0x6000000BA898, 0x0, 0x0)
30 <- Media::get_type() = 8
. -> Media::to_footage()(0x6000000BA898, 0x0, 0x0)
32 <- Media::to_footage() = 9
180 <- Clip::media_stream() = 75
. -> Footage::get_stream_from_file_index(bool, int)(0x60000032B4B8, 0x1, 0x0)
70 <- Footage::get_stream_from_file_index(bool, int) = 220
. -> ClipQueue::size()(0x7FCA8863F7A8, 0x1, 0x0)
32 <- ClipQueue::size() = 11
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x0)
24 <- Clip::media() = 12
. -> ClipQueue::lock()(0x7FCA8863F7A8, 0x1, 0x1)
31 <- ClipQueue::lock() = 9
. -> playhead_to_clip_seconds(Clip*, long)(0x7FCA8863F6C8, 0x0, 0x1)
. -> Clip::timeline_in(bool)(0x7FCA8863F6C8, 0x1, 0x1)
38 <- Clip::timeline_in(bool) = 62
. -> Clip::clip_in(bool)(0x7FCA8863F6C8, 0x1, 0x1)
33 <- Clip::clip_in(bool) = 62
. -> Clip::reversed()(0x7FCA8863F6C8, 0x1, 0x1)
29 <- Clip::reversed() = 11
. -> Clip::speed()(0x7FCA8863F6C8, 0x1, 0x1)
26 <- Clip::speed() = 12
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x1)
24 <- Clip::media() = 12
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x1)
24 <- Clip::media() = 12
. -> Media::get_type()(0x6000000BA898, 0x1, 0x1)
30 <- Media::get_type() = 8
. -> Clip::media()(0x7FCA8863F6C8, 0x1, 0x1)
24 <- Clip::media() = 12
. -> Media::to_footage()(0x6000000BA898, 0x1, 0x1)
33 <- Media::to_footage() = 9
660 <- playhead_to_clip_seconds(Clip*, long) = 204
. -> seconds_to_timestamp(Clip*, double)(0x7FCA8863F6C8, 0x1, 0x1)
. -> Clip::time_base()(0x7FCA8863F6C8, 0x1, 0x1)
34 <- Clip::time_base() = 12
. -> Cacher::media_time_base()(0x7FCA8863F790, 0x1, 0x1)
43 <- Cacher::media_time_base() = 16
226 <- seconds_to_timestamp(Clip*, double) = 119
. -> ClipQueue::size()(0x7FCA8863F7A8, 0x1, 0x1)
30 <- ClipQueue::size() = 11
. -> ClipQueue::unlock()(0x7FCA8863F7A8, 0x1, 0x1)
23 <- ClipQueue::unlock() = 9
2102 <- Cacher::Cache(long, bool, QVector<Clip*>&, int) = 612
2266 <- Clip::Cache(long, bool, QVector<Clip*>&, int) = 39
. -> Clip::Retrieve()(0x7FCA8863F6C8, 0x1062F81C4, 0x1)
. -> Media::get_type()(0x6000000BA898, 0x1062F81C4, 0x1)
30 <- Media::get_type() = 8
. -> Cacher::Retrieve()(0x7FCA8863F790, 0x1062F81C4, 0x1)
3590 <- Cacher::Retrieve() = 358
. -> Cacher::queue()(0x7FCA8863F790, 0x1062F81C4, 0x1)
29 <- Cacher::queue() = 9
. -> ClipQueue::lock()(0x7FCA8863F7A8, 0x1062F81C4, 0x1)
30 <- ClipQueue::lock() = 9
. -> Cacher::queue()(0x7FCA8863F790, 0x1, 0x7FCA88645CD0)
26 <- Cacher::queue() = 9
. -> ClipQueue::contains(AVFrame*)(0x7FCA8863F7A8, 0x7FCA88709F80, 0x7FCA88645CD0)
47 <- ClipQueue::contains(AVFrame*) = 57
. -> Cacher::media_width()(0x7FCA8863F790, 0xDE1, 0x600000019FA0)
36 <- Cacher::media_width() = 22
. -> Cacher::media_height()(0x7FCA8863F790, 0xDE1, 0x600000019FA0)
38 <- Cacher::media_height() = 22
. -> Effect::Flags()(0x7FCA8863F1D8, 0x4B000, 0x0)
29 <- Effect::Flags() = 11
. -> Cacher::queue()(0x7FCA8863F790, 0x2, 0x0)
17 <- Cacher::queue() = 9
. -> ClipQueue::unlock()(0x7FCA8863F7A8, 0x2, 0x0)
18 <- ClipQueue::unlock() = 9
5308 <- Clip::Retrieve() = 996
[...]
This is the first occurrence of a noticeably excessive elapsed time (1770575185 <- EffectRow::IsKeyframing() = 8) I'm not sure if this is significant or just an artifact of using dapptrace:
[...]
. -> TransformEffect::process_coords(double, GLTextureCoords&, int)(0x7FCA8863F1D8, 0x10DEA1C50, 0x0)
. -> DoubleField::GetDoubleAt(double)(0x6000000F5A00, 0x10DEA1C50, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000F5A00, 0x0)
. -> EffectRow::IsKeyframing()(0x6000002520F0, 0x6000000F5A00, 0x0)
42 <- EffectRow::IsKeyframing() = 8
146 <- EffectField::GetValueAt(double) = 1481
. -> DoubleField::GetDoubleAt(double)(0x6000000FDD80, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000FDD80, 0x0)
. -> EffectRow::IsKeyframing()(0x6000002520F0, 0x6000000FDD80, 0x0)
43 <- EffectRow::IsKeyframing() = 8
. -> DoubleField::GetDoubleAt(double)(0x6000000FD300, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000FD300, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B030, 0x6000000FD300, 0x0)
88 <- EffectField::GetValueAt(double) = 1481
209 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000EFF80, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000EFF80, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B030, 0x6000000EFF80, 0x0)
39 <- EffectRow::IsKeyframing() = 8
138 <- EffectField::GetValueAt(double) = 1481
251 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000ECA80, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000ECA80, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025BB10, 0x6000000ECA80, 0x0)
42 <- EffectRow::IsKeyframing() = 8
. -> DoubleField::GetDoubleAt(double)(0x6000002EBE00, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000002EBE00, 0x0)
. -> EffectRow::IsKeyframing()(0x600000256B00, 0x6000002EBE00, 0x0)
42 <- EffectRow::IsKeyframing() = 8
139 <- EffectField::GetValueAt(double) = 1481
. -> BoolField::GetBoolAt(double)(0x600000073740, 0x6, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x600000073740, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025C710, 0x600000073740, 0x0)
33 <- EffectRow::IsKeyframing() = 8
156 <- BoolField::GetBoolAt(double) = 54
. -> EffectField::GetValueAt(double)(0x10DEA1B00, 0x600000290270, 0x0)
. -> EffectRow::IsKeyframing()(0x600000256800, 0x600000290270, 0x0)
32 <- EffectRow::IsKeyframing() = 8
117 <- EffectField::GetValueAt(double) = 1481
. -> DoubleField::GetDoubleAt(double)(0x6000000F1B00, 0x10637CF18, 0x0)
. -> EffectField::GetValueAt(double)(0x10DEA1AC8, 0x6000000F1B00, 0x0)
. -> EffectRow::IsKeyframing()(0x600000256890, 0x6000000F1B00, 0x0)
1770575185 <- EffectRow::IsKeyframing() = 8
107 <- EffectField::GetValueAt(double) = 1481
198 <- DoubleField::GetDoubleAt(double) = 62
2241 <- TransformEffect::process_coords(double, GLTextureCoords&, int) = 586
[...]
The occurrences of these excessive values did seem correlated with audio playback issues though:
[...]
. -> DoubleField::GetDoubleAt(double)(0x6000002E3200, 0x10C9, 0x10C9)
. -> EffectField::GetValueAt(double)(0x10E8DABE8, 0x6000002E3200, 0x10C9)
. -> EffectRow::IsKeyframing()(0x600000447A40, 0x6000002E3200, 0x10C9)
21 <- EffectRow::IsKeyframing() = 8
76 <- EffectField::GetValueAt(double) = 1481
137 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000002E3200, 0xEF6, 0xEF6)
. -> EffectField::GetValueAt(double)(0x10E8DABE8, 0x6000002E3200, 0xEF6)
. -> EffectRow::IsKeyframing()(0x600000447A40, 0x6000002E3200, 0xEF6)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000002E3200, 0xCE1, 0xCE1)
. -> EffectField::GetValueAt(double)(0x10E8DABE8, 0x6000002E3200, 0xCE1)
. -> EffectRow::IsKeyframing()(0x600000447A40, 0x6000002E3200, 0xCE1)
22 <- EffectRow::IsKeyframing() = 8
1771128704 <- EffectField::GetValueAt(double) = 1481
133 <- DoubleField::GetDoubleAt(double) = 62
[...]
Another key-frame related occurrence:
[...]
. -> DoubleField::GetDoubleAt(double)(0x6000002E3200, 0xFFFFEC74, 0xFFFFEC74)
. -> EffectField::GetValueAt(double)(0x10E8DABE8, 0x6000002E3200, 0xFFFFEC74)
. -> EffectRow::IsKeyframing()(0x600000447A40, 0x6000002E3200, 0xFFFFEC74)
1771139543 <- EffectRow::IsKeyframing() = 8
73 <- EffectField::GetValueAt(double) = 1481
136 <- DoubleField::GetDoubleAt(double) = 62
[...]
Retrieve & process elapsed time example:
[...]
. -> Cacher::RetrieveFrameAndProcess(AVFrame**)(0x7FCA8863F790, 0x1108E6E00, 0x7FCA8B102F40)
. -> Cacher::RetrieveFrameFromDecoder(AVFrame*)(0x7FCA8863F790, 0x7FCA8849BB00, 0x0)
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x0)
23 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x3FE)
23 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x7FC)
23 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0xBFA)
22 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0xFF8)
23 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x0)
22 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x3E9)
36 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x7D2)
43 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x13F6)
44 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0xBBB)
35 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x17F6)
39 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x1BF4)
46 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0xFA4)
46 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x1FF4)
47 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x138D)
37 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x23F2)
38 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x27F0)
43 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x1776)
36 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x2BEE)
35 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x1B5F)
22 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x2FEC)
38 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x33EC)
46 <- Clip::media_stream_index() = 11
. -> Clip::media_stream_index()(0x7FCA8863F6C8, 0x0, 0x1F48)
46 <- Clip::media_stream_index() = 11
2466 <- Cacher::RetrieveFrameFromDecoder(AVFrame*) = 1156
2711 <- Cacher::RetrieveFrameAndProcess(AVFrame**) = 610
[...]
Example of what appears to be a "normal" sequence during playback:
[...]
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
. -> BoolField::GetBoolAt(double)(0x600000463080, 0x6, 0x1FF800)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x600000463080, 0x1FF800)
. -> EffectRow::IsKeyframing()(0x600000442FD0, 0x600000463080, 0x1FF800)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
136 <- BoolField::GetBoolAt(double) = 54
. -> mix_audio_sample(short, short)(0xFFFFF31F, 0x0, 0x7FCA8909E800)
25 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0xFFFFF31F, 0x0, 0x7FCA8909E800)
25 <- mix_audio_sample(short, short) = 37
. -> DoubleField::GetDoubleAt(double)(0x6000000FE880, 0x7FCA8909E8AF, 0x7FCA8909E8AC)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000FE880, 0x7FCA8909E8AC)
. -> EffectRow::IsKeyframing()(0x600000442D30, 0x6000000FE880, 0x7FCA8909E8AC)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000F9880, 0x10E8DABC4, 0x0)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000F9880, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B6C0, 0x6000000F9880, 0x0)
22 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
[...]
Example of what appears to be an abnormal sequence during playback with excessive elapsed time for mix_audio_sample() call:
[...]
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
. -> BoolField::GetBoolAt(double)(0x600000463080, 0x6, 0x1FF800)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x600000463080, 0x1FF800)
. -> EffectRow::IsKeyframing()(0x600000442FD0, 0x600000463080, 0x1FF800)
22 <- EffectRow::IsKeyframing() = 8
78 <- EffectField::GetValueAt(double) = 1481
137 <- BoolField::GetBoolAt(double) = 54
. -> mix_audio_sample(short, short)(0xFFFFF7E7, 0x0, 0x7FCA8909E800)
. -> mix_audio_sample(short, short)(0xFFFFF7E7, 0x0, 0x7FCA8909E800)
1770599778 <- mix_audio_sample(short, short) = 37
. -> DoubleField::GetDoubleAt(double)(0x6000000FE880, 0x7FCA8909E8B7, 0x7FCA8909E8B4)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000FE880, 0x7FCA8909E8B4)
. -> EffectRow::IsKeyframing()(0x600000442D30, 0x6000000FE880, 0x7FCA8909E8B4)
22 <- EffectRow::IsKeyframing() = 8
78 <- EffectField::GetValueAt(double) = 1481
143 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000F9880, 0x10E8DABC4, 0x0)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000F9880, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B6C0, 0x6000000F9880, 0x0)
22 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
[...]
And another:
[...]
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
16 <- log_volume(double) = 26
. -> BoolField::GetBoolAt(double)(0x600000463080, 0x6, 0x1FF800)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x600000463080, 0x1FF800)
. -> EffectRow::IsKeyframing()(0x600000442FD0, 0x600000463080, 0x1FF800)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
136 <- BoolField::GetBoolAt(double) = 54
. -> mix_audio_sample(short, short)(0x2C3, 0x0, 0x7FCA8909E800)
1770602512 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x2C3, 0x0, 0x7FCA8909E800)
25 <- mix_audio_sample(short, short) = 37
. -> DoubleField::GetDoubleAt(double)(0x6000000FE880, 0x7FCA8909E8C7, 0x7FCA8909E8C4)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000FE880, 0x7FCA8909E8C4)
. -> EffectRow::IsKeyframing()(0x600000442D30, 0x6000000FE880, 0x7FCA8909E8C4)
22 <- EffectRow::IsKeyframing() = 8
81 <- EffectField::GetValueAt(double) = 1481
. -> DoubleField::GetDoubleAt(double)(0x6000000F9880, 0x10E8DABC4, 0x0)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000F9880, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B6C0, 0x6000000F9880, 0x0)
22 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
[...]
And another key-frame related excessive value (these are all from one playback sequence, as I recall):
[...]
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
. -> BoolField::GetBoolAt(double)(0x600000463080, 0x6, 0x1FF800)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x600000463080, 0x1FF800)
. -> EffectRow::IsKeyframing()(0x600000442FD0, 0x600000463080, 0x1FF800)
1770604471 <- EffectRow::IsKeyframing() = 8
73 <- EffectField::GetValueAt(double) = 1481
132 <- BoolField::GetBoolAt(double) = 54
. -> mix_audio_sample(short, short)(0xA94, 0x0, 0x7FCA8909E800)
25 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0xA94, 0x0, 0x7FCA8909E800)
26 <- mix_audio_sample(short, short) = 37
. -> DoubleField::GetDoubleAt(double)(0x6000000FE880, 0x7FCA8909E8D3, 0x7FCA8909E8D0)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000FE880, 0x7FCA8909E8D0)
. -> EffectRow::IsKeyframing()(0x600000442D30, 0x6000000FE880, 0x7FCA8909E8D0)
26 <- EffectRow::IsKeyframing() = 8
99 <- EffectField::GetValueAt(double) = 1481
162 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000F9880, 0x10E8DABC4, 0x0)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000F9880, 0x0)
. -> EffectRow::IsKeyframing()(0x60000025B6C0, 0x6000000F9880, 0x0)
22 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
[...]
Additional mix_audio_sample() excessive elapsed time (seemingly sequential):
[...]
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
17 <- log_volume(double) = 26
. -> BoolField::GetBoolAt(double)(0x600000463080, 0x6, 0x1FF800)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x600000463080, 0x1FF800)
. -> EffectRow::IsKeyframing()(0x600000442FD0, 0x600000463080, 0x1FF800)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
136 <- BoolField::GetBoolAt(double) = 54
. -> mix_audio_sample(short, short)(0x14FA, 0x0, 0x7FCA8909E800)
1770609246 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x14FA, 0x0, 0x7FCA8909E800)
1770609300 <- mix_audio_sample(short, short) = 37
. -> DoubleField::GetDoubleAt(double)(0x6000000FE880, 0x7FCA8909E8EF, 0x7FCA8909E8EC)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000FE880, 0x7FCA8909E8EC)
. -> EffectRow::IsKeyframing()(0x600000442D30, 0x6000000FE880, 0x7FCA8909E8EC)
21 <- EffectRow::IsKeyframing() = 8
77 <- EffectField::GetValueAt(double) = 1481
139 <- DoubleField::GetDoubleAt(double) = 62
. -> DoubleField::GetDoubleAt(double)(0x6000000F9880, 0x10E8DABC4, 0x1)
. -> EffectField::GetValueAt(double)(0x10E8DABB8, 0x6000000F9880, 0x1)
. -> EffectRow::IsKeyframing()(0x60000025B6C0, 0x6000000F9880, 0x1)
21 <- EffectRow::IsKeyframing() = 8
76 <- EffectField::GetValueAt(double) = 1481
156 <- DoubleField::GetDoubleAt(double) = 62
. -> log_volume(double)(0x10E8DABB8, 0x6, 0x0)
27 <- log_volume(double) = 26
[...]
Additional mix_audio_sample() excessive elapsed time (but seemingly overlapping this time):
[...]
. -> apply_audio_effects(Clip*, double, AVFrame*, int, QVector<Clip*>)(0x7FCA8863F4B8, 0x7FCA8865B300, 0x1000)
. -> Effect::IsEnabled()(0x60000019B538, 0x7FCA8865B300, 0x2)
34 <- Effect::IsEnabled() = 11
. -> Effect::IsEnabled()(0x60000019DB68, 0x7FCA8865B300, 0x2)
32 <- Effect::IsEnabled() = 11
249 <- apply_audio_effects(Clip*, double, AVFrame*, int, QVector<Clip*>) = 1086
. -> get_buffer_offset_from_frame(double, long)(0xF0, 0x0, 0x2)
63 <- get_buffer_offset_from_frame(double, long) = 532
. -> mix_audio_sample(short, short)(0x0, 0x0, 0x7FCA890A3E00)
. -> mix_audio_sample(short, short)(0x0, 0x0, 0x7FCA890A3E00)
48 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x0, 0x7FCA890A3E00)
44 <- mix_audio_sample(short, short) = 37
[...]
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
25 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
25 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
25 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
26 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
51 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
51 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
53 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
38 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
42 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
42 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
38 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
1770583887 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
115 <- mix_audio_sample(short, short) = 37
. -> mix_audio_sample(short, short)(0x0, 0x1, 0x7FCA890A3E00)
1770584051 <- mix_audio_sample(short, short) = 37
[...]
For additional context, this is the last part of the output of the dapptrace run during audio playback and total calls per method:
[...]
MainWindow::metaObject() const 94
EffectUI::GetRowY(int, QWidget*) 106
Clip::media_stream_index() 109
DoubleField::UpdateWidgetValue(QWidget*, double) 111
Footage::get_stream_from_file_index(bool, int) 120
LabelSlider::SetValue(double) 122
EffectField::Now() 134
EffectRow::GetParentEffect() 134
EffectControls::metaObject() const 142
olive::styling::GetIconColor() 153
playhead_to_clip_seconds(Clip*, long) 157
Clip::speed() 158
Clip::track() 158
Clip::reversed() 171
Clip::clip_in(bool) 173
Effect::row(int) 208
Clip::timeline_in(bool) 226
Clip::timeline_out(bool) 271
EffectRow::Field(int) 275
Effect::row_count() 276
ClipQueue::size() 287
Media::to_footage() 310
frame_to_timecode(long, int, double) 310
Media::get_type() 383
BoolField::GetBoolAt(double) 462
EffectRow::FieldCount() 481
ClipQueue::at(int) 602
Clip::media() 673
log_volume(double) 798
DoubleField::GetDoubleAt(double) 1879
EffectField::GetValueAt(double) 2482
EffectRow::IsKeyframing() 2486
mix_audio_sample(short, short) 8344
I did also notice at one point that when I had the Timeline window open the audio level meter froze & stopped updating but it didn't seem to impact the audio playback one way or the other.
AUDIOWARNINGSAt one point where all audio output ceased entirely, I saw this (with AUDIOWARNINGS enabled see #911 ):
fsi-post-post:0
j0 4096
j1696 2147483647
fsi-post-post:0
j0 4096
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
j2056 2147483647
Which is in contrast to this output observed when playback seemed (mostly) correct:
fsi-post-post:0
j0 4096
j2168 2147483647
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
j664 2147483647
fsi-post-post:0
j0 4096
j3256 2147483647
And this output when audio playback was very noticeably crackly (note repeated j lines):
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
j76 2147483647
fsi-post-post:0
j0 4096
j2668 2147483647
fsi-post-post:0
j0 4096
j3028 2147483647
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
j1524 2147483647
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
j20 2147483647
fsi-post-post:0
j0 4096
j2612 2147483647
j2612 2147483647
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
fsi-post-post:0
j0 4096
j3696 2147483647
j3696 2147483647
fsi-post-post:0
j0 4096
Note that 2147483647 is INT_MAX as assigned here: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/cacher.cpp#L163-L170
(Also the nb_ prefix of nb_samples I assume means "number of samples". See: here and https://github.com/Tencent/PocketFlow/issues/279 (lol, I hadn't encountered it before either. :) ))
For the context of the j debug line see: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/cacher.cpp#L394-L414
I note this line at the end of the method: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/cacher.cpp#L474-L476
My current gut feeling continues to be some sort of lock/threading issue but also the use of INT_MAX as a magic value makes me a bit suspicious also.
I think a closer look at the logic (and additional debugging output) in Cacher::CacheAudioWorker() could be productive but the code is somewhat opaque/lengthy from an initial glance.
Hopefully this might give someone something more to go on during further investigation.
If it helps, I'll mention this isn't the first time this issue has been reported and every single person who reports it is using a Mac.
(also keep in mind that if a true cached audio backend gets implemented, this code would all probably be rewritten anyway)
I suspect there's probably multiple issues involved/affected but here's some notes from further investigation...
The issue occurs less frequently when the audio sample rate is lower. A semi-workaround that reduces the number of audio drop outs is to reduce the sample rate while editing/playing (e.g. to 22050 Hz). Then export at the full desired sample rate.
A key observation was that the partial and complete audio dropouts seemed correlated with this section of code not increasing the value of frame_sample_index: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/cacher.cpp#L417-L449
Eventually this lead to discovering that this line can lead to buffer underruns which are not detected or handled: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/audio.cpp#L213-L215
Also, note that QIODevice::write() can return -1 on error--which is not handled here (although it also doesn't appear to be the issue in this case).
Side note: I had to comment out the audio monitor because something (I think it was changing the sample rate?) led to a segmentation fault in this code: https://github.com/olive-editor/olive/blob/b819a30c01d3d3f8eed4f2befa475f7559ff8731/rendering/audio.cpp#L215-L229
I think this was related:
Olive(6073,0x1111fd000) malloc: *** error for object 0x110d98e40: pointer being freed was not allocated
*** set a breakpoint in malloc_error_break to debug
j1272 2147483647
Process 6073 stopped
* thread #10: tid = 0x76d19, 0x00007fff8aedfbc0 libsystem_malloc.dylib`malloc_error_break, name = 'AudioSenderThread', stop reason = breakpoint 1.1
frame #0: 0x00007fff8aedfbc0 libsystem_malloc.dylib`malloc_error_break
libsystem_malloc.dylib`malloc_error_break:
-> 0x7fff8aedfbc0: pushq %rbp
0x7fff8aedfbc1: movq %rsp, %rbp
0x7fff8aedfbc4: nop
0x7fff8aedfbc5: nopl (%rax)
(lldb) bt
* thread #10: tid = 0x76d19, 0x00007fff8aedfbc0 libsystem_malloc.dylib`malloc_error_break, name = 'AudioSenderThread', stop reason = breakpoint 1.1
* frame #0: 0x00007fff8aedfbc0 libsystem_malloc.dylib`malloc_error_break
frame #1: 0x00007fff8aee1028 libsystem_malloc.dylib`free + 324
frame #2: 0x0000000102ac812c QtWidgets`QVector<QWidget*>::reallocData(int, int, QFlags<QArrayData::AllocationOption>) + 316
frame #3: 0x0000000102ac7b9d QtWidgets`QWidgetBackingStore::addDirtyWidget(QWidget*, QRegion const&) + 381
frame #4: 0x0000000102ac3087 QtWidgets`QWidgetBackingStore::markDirty(QRect const&, QWidget*, QWidgetBackingStore::UpdateTime, QWidgetBackingStore::BufferState) + 967
frame #5: 0x0000000102afd312 QtWidgets`QWidget::update(QRect const&) + 274
frame #6: 0x0000000102ae58f4 QtWidgets`QWidget::update() + 52
frame #7: 0x00000001000836d4 Olive`AudioMonitor::set_value(QVector<double> const&) + 244
frame #8: 0x00000001000f04f7 Olive`AudioSenderThread::send_audio_to_output(long long, int) + 951
frame #9: 0x00000001000f00f2 Olive`AudioSenderThread::run() + 194
frame #10: 0x0000000101edfb5a QtCore`QThreadPrivate::start(void*) + 362
frame #11: 0x00007fff88a59899 libsystem_pthread.dylib`_pthread_body + 138
frame #12: 0x00007fff88a5972a libsystem_pthread.dylib`_pthread_start + 137
frame #13: 0x00007fff88a5dfc9 libsystem_pthread.dylib`thread_start + 13
Related to all this is that the assumption indicated here is not correct if a buffer underrun has occurred: https://github.com/olive-editor/olive/blob/master/rendering/cacher.cpp#L460
Here's a hacky rough patch that detects the underrun situation and didn't eliminate the crackles but did seem to prevent complete silence:
(However, it had the side effect that if the audio wasn't stopped before swapping to a different application the console was flooded with debug messages because apparently that situation needs to be handled differently. :) )
@@ -443,14 +485,20 @@ void Cacher::CacheAudioWorker() {
if (audio_thread != nullptr) audio_thread->notifyReceiver();
}
+ cout << "frame_sample_index_: " << frame_sample_index_ << " nb_bytes: " << nb_bytes << " (>=): " << (frame_sample_index_ >= nb_bytes) << std::endl;
if (frame_sample_index_ >= nb_bytes) {
frame_sample_index_ = -1;
} else {
// assume we have no more data to send
+ cout << "assumption correct?: state: " << audio_output->state() << " error: " << audio_output->error() << std::endl;
+ if ((audio_output->state() == QAudio::IdleState) && (audio_output->error()==QAudio::UnderrunError)) {
+ cout << "continue-ing" << std::endl;
+ continue;
+ }
break;
}
- // dout << "ended" << frame_sample_index << nb_bytes;
+ cout << "ended " << frame_sample_index_ << " " << nb_bytes << std::endl;
}
if (reached_end) {
frame->nb_samples = 0;
I found this piece of code which mentions "Mac OS X underruns often"--it's not entirely clear if the handling shown here would be helpful for our situation: https://github.com/juhovh/shairplay/blob/096b61ad14c90169f438e690d096e3fcf87e504e/AirTV-Qt/audiooutput.cpp#L187-L198
Here's another potentially related workaround example: https://sourceforge.net/p/viavoip/src/194/tree/audioinpanel.cpp#l495
Maybe relevant: https://github.com/qinjidong/qt5.13/blob/337798037b6b57fa0e948eb2bb1e9a409b3ea719/src/qtmultimedia/src/plugins/wasapi/qwasapiaudiooutput.cpp#L242-L254
It's also unclear if there's some approach we can take to prevent the underruns in the first place...
QAudio::IdleStateQAudio::UnderrunErrorEdit:
I鈥檝e formatted a label for one of the primary future targets, in this case cache. I strongly believe that a local cache in WAV would likely address an issue like this.
@sobotka I agree with this. Most of the playback system as it is now was designed to process in realtime (and most playback issues - video and audio - can be directly attributed to that). Though I do think @follower's findings will be very useful while redesigning a superior playback engine.
@follower easily dominates the heavyweight title for reporting.
For the sake of completeness: it turns out that rough patch breaks exporting (leads to massive CPU usage due to huge duplicatied error messages being generated), so I don't recommend using it without further modification. :) (Or compiling two Olive versions, one for editing and the other for exporting. :D )
Most helpful comment
@follower easily dominates the heavyweight title for reporting.