Re: [fluid-dev] sequencer / synth bug ?

[Antoine Schmitt]

Hello all,
I've spent more time looking into this problem, deep down below, and  
I think that I may have found a design flaw in fluid (sorry for the  
dirty word ;). I'll try to be as precise and concise as possible.

Remember that the problem is that some very short notes (like 5ms  
long) are not played at all, and the reason Mihael found is that the  
noteoff is triggered at the same time as the noteon. He hinted that  
this could be because of the 1ms accuracy of fluidsynth. I don't  
think so.

I continued Mihael's lead of the verbose flag, and extended it to the  
write_16s function, which is the function in the synththat the  
underlying audio driver calls when it needs fresh audio data for its  
buffer.

I found two problems here, and the main one is that even if the audio  
buffer sizes are set to a small value, like 64, the underlying audio  
driver asks for bursts of audio data at a time : its gets the audio  
data _ahead of time_. So the audio time of the synth is ahead of time  
with the real time, and noteon/noteoff events that are indexed on  
real time may happen _late_ compared to the audio time, and actually  
happen at the same audio time, which increases in bursts.

Here is a partial log on Mac, with a very small audio buffer of 64  
samples (audio.period-size = 64, audio.periods = 1)
(write_s16 64 6.772 means that 64 samples where asked at time 6.772 s)

fluidsynth: posting noteon  
[chan=10,key=38,vel=127,date=6819,abd=1] // this is logged by the  
sequencer
fluidsynth: sending noteoff [chan=10,key=38,date=6826,abs=1]
(...)
write_s16 64    6.772
write_s16 64    6.772
write_s16 64    6.772
write_s16 64    6.772
write_s16 64    6.773
write_s16 64    6.773
write_s16 64    6.773
write_s16 64    6.773
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.784
write_s16 64    6.785
write_s16 64    6.795
write_s16 64    6.795
write_s16 64    6.796
write_s16 64    6.796
write_s16 64    6.796
write_s16 64    6.796
write_s16 64    6.796
write_s16 64    6.796
write_s16 64    6.807
write_s16 64    6.807
write_s16 64    6.807
write_s16 64    6.807
write_s16 64    6.807
write_s16 64    6.808
write_s16 64    6.808
write_s16 64    6.808
write_s16 64    6.818
write_s16 64    6.819
write_s16 64    6.819
write_s16 64    6.819
write_s16 64    6.819
write_s16 64    6.819
write_s16 64    6.819
write_s16 64    6.819
noteon  10      38      127     00032   6.790   6.820   0.000   2
noteon  10      38      127     00032   6.790   6.820   0.000   3
noteoff 10      38      0       00032   6.790   6.826   0.000   4
noteoff 10      38      0       00032   6.790   6.826   0.000   4
write_s16 64    6.830
write_s16 64    6.830
write_s16 64    6.830
write_s16 64    6.831
write_s16 64    6.831
write_s16 64    6.831
write_s16 64    6.831
write_s16 64    6.831
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.842
write_s16 64    6.843

As you can see, the noteon and noteoff are called at the different  
times (6.820 and 6.826) which is normal but the buffer time of the  
synth is the same (6.790). As you can also see, the write_s16  
function is not called more or less every 1.45ms (which is the  
duration of 64 samples) like we would expect, it is called in bursts  
of 8 * 64 = 512 samples, more or less every 11 ms.
So it happens that a noteoff called 6ms after a noteon actually  
happens in the same synth tick (6.790 in the case above). The tick is  
the index of the next sample to be computed by the synth : it is the  
audio time. So the noteoff immediately kills the noteon even though  
they are 6ms apart.
The reason is that the tick moves ahead in bursts of about 512  
samples, not 64 samples.
This looks like a design flaw to me. In an ideal world, the write_s16  
function would check for pending events and trigger them at the right  
_audio_ moment, thus matching the audio time and the real time. But  
in the current fluidsynth, there is a fuzziness of about 512 samples,  
i.e. 11ms. Which is a lot. And which could have an effect on other  
audio events than very short notes.


The second problem that I found happens only on Windows, and it seems  
related to thread/timer priorities. On Windows, even the triggering  
times of the noteon and noteoff where late, like in Miheal's log.

Again a partial log on Windows (with audio.period-size = 64,  
audio.periods = 8) :

fluidsynth: posting noteon [chan=10,key=38,vel=127,date=2945,abd=1]
fluidsynth: sending noteoff [chan=10,key=38,date=2952,abs=1]
(...)
write_s16       128     2.894
write_s16       128     2.894
write_s16       64      2.894
write_s16       192     2.894
write_s16       128     2.904
write_s16       64      2.904
write_s16       128     2.914
write_s16       256     2.914
write_s16       128     2.914
write_s16       128     2.924
write_s16       192     2.924
write_s16       128     2.924
write_s16       128     2.924
write_s16       64      2.934
write_s16       192     2.934
write_s16       64      2.934
write_s16       128     2.934
write_s16       128     2.944
write_s16       128     2.944
write_s16       128     2.944
write_s16       128     2.944
write_s16       64      2.954
noteon  10      38      127     00002   2.808   2.954   0.000   2
noteon  10      38      127     00002   2.808   2.954   0.000   3
noteoff 10      38      0       00002   2.808   2.954   0.000   4
noteoff 10      38      0       00002   2.808   2.954   0.000   4
write_s16       64      2.954
write_s16       192     2.954
write_s16       128     2.954
write_s16       128     2.964
write_s16       64      2.964
write_s16       128     2.964
write_s16       128     2.964

We have the same burst behavior (more or less 4 requests of 128  
samples every 11 ms). But in addition, the noteon and noteoff are  
triggered at the same real time moment (2.954), even though the  
noteon was scheduled at 2945 and the noteoff at 2952. The noteon and  
noteoff events are triggered by the sequencer, which is itself  
triggered by a 1ms timer. The above means that the timer is late : it  
is even 9ms late for the noteon.
I don't understand why this would be the case.

Note that I have the full logs available for further analysis, and  
that logging did not influence the process, as I log to a memory  
buffer which I dump to file at the end.

I'd be very grateful if someone could confirm my analysis, especially  
on the problem with the bursts and its consequences on inaccuracy.  
And maybe think of ways to fix this.

Thanks,