sonic-pi
sonic-pi copied to clipboard
Published
20 hours ago •
sonic-pi-net
sonic-pi-net
OSC message lost
Hello,
While trying to record midi note_on/off event I see that some time (when pressing simultaneous notes) I loose some one (or more) of them while the note_on event is properly received and displayed in the console.
The event properly display in the "signal" log but is never 'synced'. I've tried to reproduce the issue using only OSC messages using the code below.
sleep 1
live_loop :read_osc do
use_real_time
n = sync "/osc/test"
puts n
end
live_loop :send_osc do
osc_send "127.0.0.1", 4559, "/test", 1
osc_send "127.0.0.1", 4559, "/test", 2
osc_send "127.0.0.1", 4559, "/test", 3
sleep 4
end
Observed behavior:
##| /live_loop/send_osc []
##| /osc/test [3]
##| /osc/test [2]
##| /osc/test [1]
##| /live_loop/read_osc [] -> 3
##| /live_loop/read_osc [] -> 2
I'd expect the three value to be received by the read_osc loop (at least if the flag is set to use_real_time)
##| /live_loop/send_osc []
##| /osc/test [3]
##| /osc/test [2]
##| /osc/test [1]
##| /live_loop/read_osc [] -> 3
##| /live_loop/read_osc [] -> 1
##| /live_loop/read_osc [] -> 2
Hi there,
I'm unfortunately unable to reproduce your observed behaviour locally. Could you let me know which platform you're on?
Also, could you try running the following code:
live_loop :read_osc do
use_real_time
n, _ = sync "/osc/test"
play 70
cue :received, n
end
live_loop :send_osc do
osc_send "127.0.0.1", 4559, "/test", rand
osc_send "127.0.0.1", 4559, "/test", rand
osc_send "127.0.0.1", 4559, "/test", rand
sleep 1
2.times {cue :eggs}
sleep 3
end
If you could print out your cue log here, that would be very useful indeed :-)
HI @samaaron
I'm on windows with latest version from Sonic Pi.
I've played with the amount of message sent (3 then 4 then 10) and you can see that the amount of message received vary. In my view it seems to be linked to "time".
/live_loop/send_osc []
/live_loop/read_osc []
/osc/test [0.472076416015625]
/osc/test [0.764617919921875]
/osc/test [0.957244873046875]
/cue/received [0.472076416015625]
/live_loop/read_osc []
/cue/received [0.764617919921875]
/live_loop/read_osc []
/cue/eggs []
/cue/eggs []
/live_loop/send_osc []
/osc/test [0.515594482421875]
/osc/test [0.272064208984375]
/osc/test [0.677398681640625]
/cue/received [0.515594482421875]
/live_loop/read_osc []
/cue/received [0.272064208984375]
/live_loop/read_osc []
/cue/eggs []
/cue/eggs []
=> Redefining fn :live_loop_read_osc
=> Redefining fn :live_loop_send_osc
{run: 10, time: 5.0, thread: :live_loop_read_osc}
└─ sync "/osc/test"
{run: 10, time: 5.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.957244873046875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.764617919921875]
└─ OSC -> 127.0.0.1, 4559, /test, [0.472076416015625]
{run: 10, time: 5.5144, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.472076416015625]
├─ cue :received, [0.472076416015625]
└─ sync "/osc/test"
{run: 10, time: 5.515, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.764617919921875]
├─ cue :received, [0.764617919921875]
└─ sync "/osc/test"
{run: 10, time: 6.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
{run: 10, time: 9.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.677398681640625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.272064208984375]
└─ OSC -> 127.0.0.1, 4559, /test, [0.515594482421875]
{run: 10, time: 9.5159, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.515594482421875]
├─ cue :received, [0.515594482421875]
└─ sync "/osc/test"
{run: 10, time: 9.5164, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.272064208984375]
├─ cue :received, [0.272064208984375]
└─ sync "/osc/test"
{run: 10, time: 10.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
=> Stopping all runs...
=> Starting run 4
=> Redefining fn :live_loop_read_osc
=> Redefining fn :live_loop_send_osc
{run: 4, time: 0.0, thread: :live_loop_read_osc}
└─ sync "/osc/test"
{run: 4, time: 0.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.957244873046875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.764617919921875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.472076416015625]
└─ OSC -> 127.0.0.1, 4559, /test, [0.677398681640625]
{run: 4, time: 0.5106, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.677398681640625]
├─ cue :received, [0.677398681640625]
└─ sync "/osc/test"
{run: 4, time: 0.511, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.472076416015625]
├─ cue :received, [0.472076416015625]
└─ sync "/osc/test"
{run: 4, time: 1.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
{run: 4, time: 4.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.272064208984375]
├─ OSC -> 127.0.0.1, 4559, /test, [0.515594482421875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.209259033203125]
└─ OSC -> 127.0.0.1, 4559, /test, [0.859161376953125]
{run: 4, time: 4.515, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.859161376953125]
├─ cue :received, [0.859161376953125]
└─ sync "/osc/test"
{run: 4, time: 4.516, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.515594482421875]
├─ cue :received, [0.515594482421875]
└─ sync "/osc/test"
{run: 4, time: 4.517, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.272064208984375]
├─ cue :received, [0.272064208984375]
└─ sync "/osc/test"
{run: 4, time: 5.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
{run: 4, time: 8.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.238189697265625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.03424072265625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.233367919921875]
└─ OSC -> 127.0.0.1, 4559, /test, [0.057586669921875]
{run: 4, time: 8.5102, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.057586669921875]
├─ cue :received, [0.057586669921875]
└─ sync "/osc/test"
{run: 4, time: 8.5107, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.233367919921875]
├─ cue :received, [0.233367919921875]
└─ sync "/osc/test"
{run: 4, time: 8.5112, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.238189697265625]
├─ cue :received, [0.238189697265625]
└─ sync "/osc/test"
{run: 4, time: 9.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
=> Stopping all runs...
=> Stopping run 4
=> Completed run 4
=> All runs completed
=> Pausing SuperCollider Audio Server
=> Starting run 5
=> Redefining fn :live_loop_read_osc
=> Redefining fn :live_loop_send_osc
{run: 5, time: 0.0, thread: :live_loop_read_osc}
└─ sync "/osc/test"
{run: 5, time: 0.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.957244873046875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.764617919921875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.472076416015625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.677398681640625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.272064208984375]
├─ OSC -> 127.0.0.1, 4559, /test, [0.515594482421875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.209259033203125]
├─ OSC -> 127.0.0.1, 4559, /test, [0.859161376953125]
├─ OSC -> 127.0.0.1, 4559, /test, [0.238189697265625]
└─ OSC -> 127.0.0.1, 4559, /test, [0.03424072265625]
{run: 5, time: 0.5149, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.03424072265625]
├─ cue :received, [0.03424072265625]
└─ sync "/osc/test"
{run: 5, time: 0.5159, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.515594482421875]
├─ cue :received, [0.515594482421875]
└─ sync "/osc/test"
{run: 5, time: 1.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
{run: 5, time: 4.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.233367919921875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.057586669921875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.03759765625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.959930419921875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.2010498046875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.38134765625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.599822998046875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.038726806640625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.77362060546875]
└─ OSC -> 127.0.0.1, 4559, /test, [0.8564453125]
{run: 5, time: 4.5096, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.8564453125]
├─ cue :received, [0.8564453125]
└─ sync "/osc/test"
{run: 5, time: 4.5106, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.2010498046875]
├─ cue :received, [0.2010498046875]
└─ sync "/osc/test"
{run: 5, time: 4.5116, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.03759765625]
├─ cue :received, [0.03759765625]
└─ sync "/osc/test"
{run: 5, time: 4.5126, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.233367919921875]
├─ cue :received, [0.233367919921875]
└─ sync "/osc/test"
{run: 5, time: 5.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
{run: 5, time: 8.0, thread: :live_loop_send_osc}
├─ OSC -> 127.0.0.1, 4559, /test, [0.9029541015625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.0848388671875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.748870849609375]
├─ OSC -> 127.0.0.1, 4559, /test, [0.8543701171875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.471099853515625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.04547119140625]
├─ OSC -> 127.0.0.1, 4559, /test, [0.686798095703125]
├─ OSC -> 127.0.0.1, 4559, /test, [0.042694091796875]
├─ OSC -> 127.0.0.1, 4559, /test, [0.110748291015625]
└─ OSC -> 127.0.0.1, 4559, /test, [0.147125244140625]
{run: 5, time: 8.5112, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.147125244140625]
├─ cue :received, [0.147125244140625]
└─ sync "/osc/test"
{run: 5, time: 8.5117, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.042694091796875]
├─ cue :received, [0.042694091796875]
└─ sync "/osc/test"
{run: 5, time: 8.5122, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.471099853515625]
├─ cue :received, [0.471099853515625]
└─ sync "/osc/test"
{run: 5, time: 8.5132, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.0848388671875]
├─ cue :received, [0.0848388671875]
└─ sync "/osc/test"
{run: 5, time: 8.5137, thread: :live_loop_read_osc}
├─ synced "/osc/test"
├─ synth :beep, {note: 70.0}
├─ set :received, [0.9029541015625]
├─ cue :received, [0.9029541015625]
└─ sync "/osc/test"
{run: 5, time: 9.0, thread: :live_loop_send_osc}
├─ set :eggs, []
├─ cue :eggs, []
├─ set :eggs, []
└─ cue :eggs, []
=> Stopping all runs...
=> Stopping run 5
=> Completed run 5
=> All runs completed
=> Pausing SuperCollider Audio Server
Hi @samaaron
I've put some debug here and there in event_history.rb to dump the state of the events and compared it with the received cue value.
Here's the finding so far:
/osc/test [0.03424072265625]
/osc/test [0.238189697265625]
/osc/test [0.859161376953125]
/osc/test [0.209259033203125]
/osc/test [0.272064208984375]
/osc/test [0.677398681640625]
/osc/test [0.472076416015625]
/osc/test [0.764617919921875]
/osc/test [0.957244873046875]
/osc/test [0.515594482421875]
events.each {
|se|
puts "event in history #{se.time.strftime("%M:%S:%L:%N")}, #{se.priority}, #{se.thread_id}, #{se.delta}, #{se.beat}, #{se.bpm} #{se.val}"
}
->
OK event in history 36:35:131:131687000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.515594482421875]
KO event in history 36:35:131:131186000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.957244873046875]
OK event in history 36:35:131:131186000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.764617919921875]
KO event in history 36:35:130:130683000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.472076416015625]
KO event in history 36:35:130:130683000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.677398681640625]
OK event in history 36:35:130:130683000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.272064208984375]
OK event in history 36:35:129:129682000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.209259033203125]
KO event in history 36:35:129:129182000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.859161376953125]
OK event in history 36:35:129:129182000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.238189697265625]
OK event in history 36:35:128:128682000, 0, #<SonicPi::ThreadId [-1]>, 0, 0.0, 60.0 [0.03424072265625]
/cue/received [0.03424072265625]
/live_loop/read_osc []
/cue/received [0.238189697265625]
/live_loop/read_osc []
/cue/received [0.209259033203125]
/live_loop/read_osc []
/cue/received [0.272064208984375]
/live_loop/read_osc []
/cue/received [0.764617919921875]
/live_loop/read_osc []
/cue/received [0.515594482421875]
/live_loop/read_osc []
As you can see, some event have exactly the same 'time' value and for these one, only the latest is returned. I guess this is the culprit.
Excellent sleuthing - thanks so much. This is definitely enough to go on.
Interestingly, I was able to reproduce this behaviour on my Windows VM, but on my Mac, all the messages always were received.
Thank you @samaaron I guess time precision is "lower" on ruby windows.
I might have some time to try to propose a fix for this issue this weekend. Do you have some guidance on how you would like the solution to be approached?
I'd see it either at event creation/state insertion, making sure time key is unique or at get_next making sure to iterate over events with identical times.
Hello @slvlirnoff - it's possible this issue is related to the accuracy of timing in Erlang on Windows. If so, it's possible this issue is solved with updates to Erlang's timing resolution on Windows, included in the upcoming release of Sonic Pi v4.0. If you are a Patreon, you'll be able to test this out with our Betas available there - otherwise this may be solved when the official v4.0 release is out in the (hopefully) not too distant future.
@ethancrawford hey, do you know if this has been fixed in the latest 4.x release? I will try at some point and see if I can reproduce the issue.