Sonic pi thread got too far behind time when sending many OSC events

Support, Help & Resources
1

Hi I’m facing the sonic pi thread got too far behind time exception in my setup.
I wanted to check if there is a way to change what I did so that what I’m trying to make can work.

Basically, I’m trying to generate music from a Gradle build.
From those of you who don’t know Gradle, it’s a build tool for (mostly) JVM-based projects.

Gradle emits events when certain things happen, such as a build is started, finished, a ‘task’ is started/finished (a task being an atomic piece of work in Gradle).

When such events happen, I send via OSC a message to SonicPi, with a format like /event/build/<<unique-id>>/started, or /event/task/<<unique-id>>/finished (you get the picture).
When a ‘started’ event is received, Sonic PI is supposed to start a new thread, that will eventually contain a loop playing some stuff (different if it’s a build, a task, or other kind of events).
When a ‘finished’ event is received, the corresponding thread and the eventual loops it contains is stopped.
So far, so good, and it works in a very simple setup.

Now, Gradle is very fast, it can execute tasks in parallel, or tasks can be very fast.
In such scenarios, I’m seeing thread got too far behind time very early in the build.

To try to cope with it, I adding an ‘ack’ response back to the code that is sending the OSC events.
So basically, even if that code is trying to send a lot of things almost at the same time (say with only a few milliseconds of interval), it will wait for an ‘ack’ response from SonicPi before sending the next one. The ‘ack’ essentially means that SonicPi received the OSC message, and dealt with it (created a thread, or stopped it). Even there, still the same problem.

I’m using a bpm of 90, and I’m also using use_real_time in the thread that waits for OSC message.

All of this communication happens on the same machine, which is a 2018 MacbookPro, with 32Gb of ram.
Basically my questions are the following:

  • Is this expected to see such problems when sending many events within the same second to Sonic Pi, even on a rather powerful machine ?
  • How can I troubleshoot this to make sure this is really a limitation in SonicPi that I can’t do nothing about ?
  • How can I mitigate this ? (Sth like catching the exception to avoid the errors popping up and kill the thread and related loops if it happens)

I can show you some code if my explanation is not enough.

2

It would be useful to see the code, where we might be able to spot any problems. In my experience SP is not bad at handling large numbers of osc messages in a short space of time, which I have used in several of my projects.

3

Here’s the Sonic Pi code

# Gradle music
use_osc_logging false
use_debug false
use_cue_logging false
use_midi_logging false

use_bpm 90
use_timing_guarantees true
use_osc "localhost", 4560

#########################################################
# INIT: when the Gradle builds emits an init event
#########################################################

define :initStarted do |live_loop_name, args|
  loop_kill_switch = loop_kill_switch(live_loop_name).to_sym
  live_loop live_loop_name.to_sym do
    maybeKillLiveLoop(live_loop_name, loop_kill_switch)
    use_synth :fm
    use_octave -2
    3.times do
      play c[0]
      sleep 1
    end
    play c[2]
    sleep 0.5
    play c[1]
    sleep 0.5
    c = chords.tick
  end
end

define :initFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name)
end

#########################################################
# BUILD : when the Gradle builds emits an build event
#########################################################

define :buildStarted do |live_loop_name, args|
  loop1 = live_loop_name + "_blade"
  loop_1_kill_switch = loop_kill_switch(loop1).to_sym
  live_loop (loop1).to_sym do
    maybeKillLiveLoop(live_loop_name, loop_1_kill_switch)
    use_synth :blade
    play c
    sleep 2
  end
end

define :buildFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name + "_blade")
end

#########################################################
# TASK: : when the Gradle builds emits an task event
#########################################################

define :taskStarted do |live_loop_name, args|
  loop1 = live_loop_name + "_blade"
  loop_1_kill_switch = loop_kill_switch(loop1).to_sym
  live_loop (loop1).to_sym  do
    maybeKillLiveLoop(live_loop_name, loop_1_kill_switch)
    use_synth :blade
    r = [0.25, 0.25, 0.5, 1].choose
    play c.choose, attack: 0, release: r
    sleep r
  end
end

define :taskFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name + "_blade")
end

#########################################################
# Helper methods
#########################################################

# OSC bus live loop
# Receives OSC events and trigger live_loop creation or stopping based on the passed data
live_loop :osc_bus do
  use_real_time
  # Wait on an OSC event at that address
  args = sync "/osc*/event/**"
  input_event = parse_sync_address "/osc*/event/**"
  puts "Received event: " + input_event.to_s
  type = input_event[2]
  unique_id = input_event[3]
  action = input_event[4]
  
  loopName = loop_name(type, unique_id)
  case action
  when "started"
    event_started(type, loopName, args)
  when "finished"
    event_finished(type, loopName, args)
  else
    puts "Unknown action: " + action
    stop
  end
  # Ping back that we are ready to receive a new OSC event
  # The Gradle builds waits for this 'ack' OSC message before moving on
  osc_send "localhost", 57110, "/ack"
end


# Creates a thread creating a live_loop which is monitoring when it should stop itself
define :event_started do |type, live_loop_name, args|
  in_thread(name: (live_loop_name + "_createthread").to_sym) do
    case type
    when "init"
      initStarted(live_loop_name, args)
    when "build"
      buildStarted(live_loop_name, args)
    when "task"
      taskStarted(live_loop_name, args)
    else
      puts "Unknown type: " + type
      stop
    end
  end
end

# Creates a thread that is eventually going to stop a live_loop after some sleep
define :event_finished do |type, live_loop_name, args|
  in_thread(name: (live_loop_name + "_killthread").to_sym) do
    case type
    when "init"
      initFinished(live_loop_name, args)
    when "build"
      buildFinished(live_loop_name, args)
    when "task"
      taskFinished(live_loop_name, args)
    else
      puts "Unknown type: " + type
      stop
    end
  end
end

define :parse_sync_address do |address|
  # puts address #-> ""/osc*/event/**""
  # puts get_event(address).to_s.split(",")[6] #-> " \"/osc:127.0.0.1:4560/event/project/0/started/bd_haus\""
  v = get_event(address).to_s.split(",")[6]
  if v != nil
    # puts v[3..-2] #-> "osc:127.0.0.1:4560/event/project/0/started/bd_haus"
    puts v[3..-2].split("/") #-> "["osc:127.0.0.1:4560", "event", "project", "0", "started", "bd_haus"]"
    return v[3..-2].split("/")
  else
    puts "Error in :parse_sync_address: v=nil"
    stop
  end
end

# function to define a unique name based on the type and unique id
define :loop_name do |type, unique_id|
  return type + "_" + unique_id
end

# function to define the unique live_loop kill switch
define :loop_kill_switch do |live_loop_name|
  return live_loop_name + "_kill"
end

# function to define the unique live_loop kill switch
define :loop_kill_delta do |live_loop_name|
  return live_loop_name + "_delta"
end

define :setKillLiveLoopSwitch do |live_loop_name|
  loop_kill_switch = loop_kill_switch(live_loop_name).to_sym
  set loop_kill_switch, 1
end

define :maybeKillLiveLoop do |live_loop_name, loop_kill_switch|
  if get(loop_kill_switch) == 1
    set loop_kill_switch, 0
    stop
  end
end

The entry point is the :osc_bus live_loop, that is going to wait for an OSC message, like

  • osc:127.0.0.1:4560/event/init/0/started
  • osc:127.0.0.1:4560/event/project/1/started
  • osc:127.0.0.1:4560/event/task/2/started
  • osc:127.0.0.1:4560/event/task/2/finished
  • osc:127.0.0.1:4560/event/task/3/started
  • osc:127.0.0.1:4560/event/task/3/finished
  • osc:127.0.0.1:4560/event/task/4/started
  • osc:127.0.0.1:4560/event/task/4/finished
  • osc:127.0.0.1:4560/event/project/1/finished
  • osc:127.0.0.1:4560/event/init/0/finished

This sequence above is very simple (init, project, then 3 tasks, then project finished, init finished).
You can imagine having way more task events sent, very close to each others (only a few millis apart), and overlapping (i.e. several ‘started’ tasks before some ‘finished’ tasks, due to the Gradle build’s parallelism)

When the action is ‘started’, the :event_started function is called, that starts a thread.
When the action is ‘finished’, the :event_finished function is called, that starts another thread.
I’m using threads here to unblock as soon as possible the main thread (the one of the :osc_bus live_loop), so that it can answer with ‘ack’ as soon as possible and be ready to accept a new incoming OSC message.

The :event_started thread calls initStarted, buildStarted or taskStarted based on the action grabbed from the OSC message. Those functions define what melody to play based on the kind of event received.
The :event_finished thread will essentially set some global variable in TimeState to stop the created live_loop previously created for that event.

Hope this helps you figure out what the problem might be.

4

This is some quite cool code, which took a bit of getting used to. It reminded me of a former project I did on a Sonic Pi loop controller
I wasn’t sure where the c and chords variables were supposed to come from so I added them to get going. I set up TouchOSC to produce input osc messages similar to the ones you specified, although I changed project to build as there didn’t seem to be any reference to project in your code. The result was a system that seemed to work quite well, although the loading of osc messages in this manner was not going to be that rapid.
But at least I could see the code in action. I think to get any further I would need to set up gradle to get a faster input stream.

My modified program is below set up for TouchOSC on a different ip address (only relevant to see that the ack message was working.

#add some data for chords and c
chords=(ring [:c4,:e4,:g4],[:e4,:g4,:c5],[:f4,:a4,:d5],[:g4,:c5,:e5])
c=[:c4,:e4,:g4]

# Gradle music
use_osc_logging false
use_debug false
use_cue_logging false
use_midi_logging false

use_bpm 90
use_timing_guarantees true
use_osc "localhost", 4560 #not sure that you need this. only using osc_send for /ack

#########################################################
# INIT: when the Gradle builds emits an init event
#########################################################

define :initStarted do |live_loop_name, args|
  loop_kill_switch = loop_kill_switch(live_loop_name).to_sym
  live_loop live_loop_name.to_sym do
    maybeKillLiveLoop(live_loop_name, loop_kill_switch)
    use_synth :fm
    use_octave -2
    3.times do
      play c[0]
      sleep 1
    end
    play c[2]
    sleep 0.5
    play c[1]
    sleep 0.5
    c = chords.tick
  end
end

define :initFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name)
end

#########################################################
# BUILD : when the Gradle builds emits an build event
#########################################################

define :buildStarted do |live_loop_name, args|
  loop1 = live_loop_name + "_blade"
  loop_1_kill_switch = loop_kill_switch(loop1).to_sym
  live_loop (loop1).to_sym do
    maybeKillLiveLoop(live_loop_name, loop_1_kill_switch)
    use_synth :blade
    play c
    sleep 2
  end
end

define :buildFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name + "_blade")
end

#########################################################
# TASK: : when the Gradle builds emits an task event
#########################################################

define :taskStarted do |live_loop_name, args|
  loop1 = live_loop_name + "_blade"
  loop_1_kill_switch = loop_kill_switch(loop1).to_sym
  live_loop (loop1).to_sym  do
    maybeKillLiveLoop(live_loop_name, loop_1_kill_switch)
    use_synth :blade
    r = [0.25, 0.25, 0.5, 1].choose
    play c.choose, attack: 0, release: r
    sleep r
  end
end

define :taskFinished do |live_loop_name, args|
  setKillLiveLoopSwitch(live_loop_name + "_blade")
end

#########################################################
# Helper methods
#########################################################

# OSC bus live loop
# Receives OSC events and trigger live_loop creation or stopping based on the passed data
live_loop :osc_bus do
  use_real_time
  # Wait on an OSC event at that address
  args = sync "/osc*/event/**"
  input_event = parse_sync_address "/osc*/event/**"
  puts "Received event: " + input_event.to_s
  type = input_event[2]
  unique_id = input_event[3]
  action = input_event[4]
  
  loopName = loop_name(type, unique_id)
  case action
  when "started"
    event_started(type, loopName, args)
  when "finished"
    event_finished(type, loopName, args)
  else
    puts "Unknown action: " + action
    stop
  end
  # Ping back that we are ready to receive a new OSC event
  # The Gradle builds waits for this 'ack' OSC message before moving on
  osc_send "192.168.1.232", 9000, "/event/ack",1 #changed to suit TouchOSC!) 
  sleep 0.05
  osc_send "192.168.1.232", 9000, "/event/ack",0
end


# Creates a thread creating a live_loop which is monitoring when it should stop itself
define :event_started do |type, live_loop_name, args|
  in_thread(name: (live_loop_name + "_createthread").to_sym) do
    case type
    when "init"
      initStarted(live_loop_name, args)
    when "build"
      buildStarted(live_loop_name, args)
    when "task"
      taskStarted(live_loop_name, args)
    else
      puts "Unknown type: " + type
      stop
    end
  end
end

# Creates a thread that is eventually going to stop a live_loop after some sleep
define :event_finished do |type, live_loop_name, args|
  in_thread(name: (live_loop_name + "_killthread").to_sym) do
    case type
    when "init"
      initFinished(live_loop_name, args)
    when "build"
      buildFinished(live_loop_name, args)
    when "task"
      taskFinished(live_loop_name, args)
    else
      puts "Unknown type: " + type
      stop
    end
  end
end

define :parse_sync_address do |address|
  # puts address #-> ""/osc*/event/**""
  # puts get_event(address).to_s.split(",")[6] #-> " \"/osc:127.0.0.1:4560/event/project/0/started/bd_haus\""
  v = get_event(address).to_s.split(",")[6]
  if v != nil
    # puts v[3..-2] #-> "osc:127.0.0.1:4560/event/project/0/started/bd_haus"
    puts v[3..-2].split("/") #-> "["osc:127.0.0.1:4560", "event", "project", "0", "started", "bd_haus"]"
    return v[3..-2].split("/")
  else
    puts "Error in :parse_sync_address: v=nil"
    stop
  end
end

# function to define a unique name based on the type and unique id
define :loop_name do |type, unique_id|
  return type + "_" + unique_id
end

# function to define the unique live_loop kill switch
define :loop_kill_switch do |live_loop_name|
  return live_loop_name + "_kill"
end

# function to define the unique live_loop kill switch
define :loop_kill_delta do |live_loop_name|
  return live_loop_name + "_delta"
end

define :setKillLiveLoopSwitch do |live_loop_name|
  loop_kill_switch = loop_kill_switch(live_loop_name).to_sym
  set loop_kill_switch, 1
end

define :maybeKillLiveLoop do |live_loop_name, loop_kill_switch|
  if get(loop_kill_switch) == 1
    set loop_kill_switch, 0
    stop
  end
end

IMG_83846E5BCC87-1
IMG_83846E5BCC87-11536×2048 108 KB

5

I wasn’t sure where the c and chords variables were supposed to come from

Yeah, I overly simplified the script and forgot to declare them. Doesn’t matter much though.

I changed project to build as there didn’t seem to be any reference to project in your code.

My bad again, I intend to have build / project / task / console log, test, etc in the future, but really for now was just focusing on build and task. Sorry for the confusion.

to get any further I would need to set up gradle to get a faster input stream.

Let me prepare a little self-contained Gradle project, push that to GitHub. Then you can just launch SonicPi, and then execute the Gradle build (nothing needed except a JDK 8 on your machine). I’ll come back to you shortly when this is prepared.

6

@robin.newman
Here you go: https://github.com/facewindu/GradleSonicPi
I added some information on the README.md file. It should be enough to get you going and reproduce the problem.

7

I’ll take a look tomorrow.

8

I set it up today and have had a good play. I can confirm I get the same errors, although not initially (with the number of events set to 150), but particularly on subsequent runs after the first one. You have a fairly complex set up of threads, and I suspect that the method of killing them may not perform as cleanly as we would like, even though it is something that I suggested and used previously in my own software! I notice that if you press stop after a run the log (if you activate it), would normally says something like

=> Stopping all runs...

=> Stopping run 2

> Completed run 2

=> All runs completed

=> Pausing SuperCollider Audio Server

However in the case of your software, if you stop the run after the gradle script has completed it just says:

=> Stopping all runs...

=> Stopping run 2

signifying that something is still active and unfinished.
If I do subsequent runs from this point I find that it fairly quickly degrades with get behind errors.
If I stop and restart Sonic Pi, then I have been able to adjust the number of tasks up to 1500 and play successfully with a few getting behind errors but no threads crashing completely. I’m not sure if this can be emulated from within the software without restarting.

The other thing I notice is that in order to get unique thread names you have a a uniqueID incorporated which is quite long, and this will build up a large symbol table which may take some time to search for matches. Maybe you can get away with a shorter ID.

@samaaron may like to comment on your software. It is certainly something which is going to stress Sonic Pi quite severely I think, but it may be that there are changes that can be made to make it work better.

9

I think this is similar to what I experienced with my attempts to use SP for Monome applications (developement stopped; code for Open Stage Control and Monome grid).

This is kind of hard to reproduce with a simple setup because IMHO the sheer amount of OSC messages and interaction seems to be the reason. There is for sure space for improvements of the code but as far as I see the performance breaks down to early - at least for that kind of application.

10

Thanks guys

@Martin any idea about improvements on the sonic pi side, nevertheless?
I’ll experiment with some improvements such as sending the number of running live loops back to the gradle build, and defer creating more until the live loop number goes down to an acceptable level.

Also my example is not realistic. Having so many Gradle tasks that do nothing and are very fast is unlikely. I can defer the task handling until both the task started and task finished event are known on the gradle side. Then, based on the task duration I can decide to trigger a live loop or just play a few notes outside a live loop.

Quick question too:
I’m using live loops but I don’t intend to modify them live. Will it be better to just use loops? Would it improve performance?

11

Hi @facewindu,

I don’t think I can be of any specific help. I kind of abandoned these projects because I don’t believe it is worth to put more time into it.

  • There was this issue which seems to be resolved more or less; it improved things but did not improve the performance as much as I hoped. But … be sure you are running a version of Sonic Pi with that fix (I guess you are because the last update on the issue was in April).
  • for sure it is a good idea to reduce the number of live_loops running as far as possible (maybe you can combine things? e. g. in the beginning I had several live_loops which listened to incoming OSC signals, I think I reduced that to one)
  • also it is clear the shorter the runtime of you loops the more load is produced (of course if a live loop is listening in real time this is dependent on the live input and you do not have a choice; in my case the runtime of the live loops was defined by the rhythmic resolution I needed (e. g. sixteenth notes))
  • whether you are using live_loop of just ‘simple’ loops? I don’t know. Just set up a test case. Maybe Sam can answer this.

Disclaimer: And last but not least: I am by no means an expert coder and thus I can’t guarantee the quality and correctness of these ideas.

So far…

12

I made some changes to the example project, and it seems to be much better.
I ditched using live loops as I don’t intend to modify the music live for now.
The main change is about the logic to stop playing music when a finished event happens. Instead of stopping the live loop, I’m using direct Ruby code to kill the current thread. It seems to behave much better. I didn’t get ‘too far behind errors’, even when changing the number of Gradle tasks to a larger number and reducing the sleep in each task.
@robin.newman you might be interested by this code.

1 Like
13

Interesting. I’ll take a look later today.
EDIT
gave it a go. Much better. Ran fine with 1000 tasks. Also when you then stopped the program it stopped correctly. Definitely the way to go.