rsc3/doc-schelp/HelpSource/Guides/Debugging-tips.scrbl

#lang scribble/manual
@(require (for-label racket))

@title{Debugging tips}
 tips on debugging synthdefs, client code and more@section{categories}
  Language, Debugging
@section{related}
  Guides/Understanding-Errors

@section{section}
  Debugging synthdefs

The challenge in debugging synthdefs is the invisibility of the server's operations. There are a handful of techniques to expose the output of various UGens.

@section{subsection}
  SendTrig / OSCFunc

SendTrig is originally intended to send a trigger message back to the client, so the client can take further action on the server. However, it can be used to send any numeric value back to the client, which can then be printed out.

To print out the values, you need to create an OSCFunc as follows:

@racketblock[
o = OSCFunc({ |msg| msg.postln }, '/tr', s.addr);
::
Each line of output is an array with four values: ]

@racketblock[ ['/tr', defNode, id (from SendTrig), value (from SendTrig)] ::.

]

@racketblock[
{	var	freq;
	freq = LFNoise1.kr(2, 600, 800);
		// Impulse is needed to trigger the /tr message to be sent
	SendTrig.kr(Impulse.kr(4), 0, freq);
	SinOsc.ar(freq, 0, 0.3) ! 2
}.play;
[ /tr, 1000, 0, 1340.8098144531 ]
[ /tr, 1000, 0, 1153.9201660156 ]
[ /tr, 1000, 0, 966.35247802734 ]
[ /tr, 1000, 0, 629.31628417969 ]

o.free;  // when done, you need to clean up the OSCFunc
::

If you need to track multiple values, SendReply can send arrays of values back to the client.

]

@racketblock[
l = List.new;
o = OSCFunc({ |msg|
		// msg[3] is the first array value
		// [3..] means take everything in the array after that
	l.add(msg[3..]);
}, '/freqAmp', s.addr);

a = {
	var	freq, amp;
	freq = LFNoise0.kr(8, 600, 800);
	amp = LFNoise1.kr(10, 0.5, 0.5);
		// Impulse is needed to trigger the reply to be sent
	SendReply.kr(Impulse.kr(4), '/freqAmp', [freq, amp]);
	SinOsc.ar(freq, 0, amp) ! 2
}.play;

a.free;
o.free;  // when done, you need to clean up the OSCFunc

// plot as two channels: frequencies in the top graph, amps in the bottom
l.flat.plot(numChannels: 2);
::

]
@section{subsection}
  Polling

Polling allows you to debug a SynthDef by printing samples of a UGen's output to the post window. To do this, use the .poll method (a shorthand for the Poll UGen), which prints 10 times per second by default.


@racketblock[
{ LFNoise1.kr.poll; }.play;   // default poll
::

This can be too fast, so you can specify how many times per second the value should be printed.

]

@racketblock[
{ LFNoise1.kr.poll(3); }.play;  // poll more slowly
::

You can also poll arrays

]

@racketblock[
{ [LFNoise1.kr, LFNoise1.kr].poll; }.play;  // poll an array
::

For more than one value or array at once, poll can become unwieldy, because so many values are printed to the screen that it is difficult to tell which is which. Labels help with this.

]

@racketblock[
{ LFNoise1.kr.poll(3, "a value"); LFNoise1.kr.poll(5, "another value"); }.play;
::

Debugging triggers doesn't work with regular polling, because the trigger will mostly occur in between polling intervals. The output itself can be supplied instead of the number of polls per second. This way, the value is only printed when there is a trigger, rather than at a regular interval.

]

@racketblock[
{ var trig = Dust.kr; trig.poll(trig); }.play;
::

You can debug a value that changes infrequently in a similar way, using the Changed UGen. This only prints the value when it just changed.

Note that it will skip changes that occur immediately after a previous change, because any trigger needs to revert back to zero before triggering again.

]

@racketblock[
{ var steps = LFNoise0.kr; steps.poll(Changed.kr(steps); }.play;
::

You can also use a seperate trigger. This is useful for having the most control over when a poll occurs.

]

@racketblock[
~synth={ arg t_trig; [LFNoise1.kr, LFNoise1.kr].poll(t_trig); }.play;

// the t_ in t_trig is shorthand to cause ~synth.set(\t_trig, 1) to trigger instead of set permanently
~synth.set(\t_trig, 1); // run this line a couple of times 
::

All the examples above work the same for audio rate UGens.

]

@racketblock[
{ LFNoise1.ar.poll; }.play;
::

]
@section{subsection}
  Trace control signals using a control bus

Another technique to watch control values is to output the signal to a control-rate bus. Then you can access the bus using link::Classes/Bus#-get:: or link::Classes/Bus#-getSynchronous::. Saving the values into an Array or List is a little more straightforward with getSynchronous.


@racketblock[
b = Bus.control(s, 1);

a = {
	var	freq;
	freq = LFNoise1.kr(2, 600, 800);
	Out.kr(b, freq);		// no need for Impulse here
	SinOsc.ar(freq, 0, 0.3) ! 2
}.play;

l = List.new;
r = fork { loop { l.add(b.getSynchronous); 0.1.wait } };

r.stop;
a.free;

l.array.plot;  // to view the results graphically
::

This works only with internal or local servers. For remote servers, the routine may be rewritten as follows.

]

@racketblock[
r = fork { loop { b.get({ |value| l.add(value) }); 0.1.wait } };
::

]
@section{note}
 This approach is not valid for audio buses, because the data move too quickly to support 'get'.::

@section{subsection}
  Server-side trace

The 
@racketblock[/n_trace:: message causes the server to print a list of all the UGens in the node as well as their input and output values.

It takes some practice to read a synthdef trace, but it's the ultimate source of information when a synthdef is not behaving as expected. Signal flow can be identified by looking at the numbers at inputs and outputs. When a UGen's output feeds into another's input, the values will be the same at both ends.

For a concrete example, let's look at a synthdef that doesn't work. The intent is to generate a detuned sawtooth wave and run it through a set of parallel resonant filters whose cut-off frequencies are modulating randomly.
We run the synth and generate the trace (reproduced below).
]

@racketblock[
SynthDef(\resonz, { |freq = 440|
	var	sig, ffreq;
	sig = Saw.ar([freq, freq+1], 0.2);
	ffreq = LFNoise1.kr(2, 1, 0.5);
	Out.ar(0, Resonz.ar(sig, (800, 1000..1800) * ffreq, 0.1))
}).send(s);

a = Synth(\resonz);
a.trace;
a.free;

		TRACE 1005  resonz    #units: 21
		  unit 0 Control
		    in
		    out 440
		  unit 1 BinaryOpUGen
		    in  440 1
		    out 441
		  unit 2 Saw
		    in  441
		    out 0.451348
		  unit 3 BinaryOpUGen
		    in  0.451348 0.2
		    out 0.0902696
		  unit 4 Saw
		    in  440
		    out -0.367307
		  unit 5 BinaryOpUGen
		    in  -0.367307 0.2
		    out -0.0734615
		  unit 6 LFNoise1
		    in  2
		    out -0.836168
		  unit 7 BinaryOpUGen
		    in  -0.836168 0.5
		    out -0.336168
		  unit 8 BinaryOpUGen
		    in  800 -0.336168
		    out -268.934
		  unit 9 Resonz
		    in  -0.0734615 -268.934 0.1
		    out 843934
		  unit 10 BinaryOpUGen
		    in  1000 -0.336168
		    out -336.168
		  unit 11 Resonz
		    in  0.0902696 -336.168 0.1
		    out 3.02999e+08
		  unit 12 BinaryOpUGen
		    in  1200 -0.336168
		    out -403.402
		  unit 13 Resonz
		    in  -0.0734615 -403.402 0.1
		    out 9.14995e+10
		  unit 14 BinaryOpUGen
		    in  1400 -0.336168
		    out -470.635
		  unit 15 Resonz
		    in  0.0902696 -470.635 0.1
		    out -5.42883
		  unit 16 BinaryOpUGen
		    in  1600 -0.336168
		    out -537.869
		  unit 17 Resonz
		    in  -0.0734615 -537.869 0.1
		    out 515.506
		  unit 18 BinaryOpUGen
		    in  1800 -0.336168
		    out -605.102
		  unit 19 Resonz
		    in  0.0902696 -605.102 0.1
		    out 32785.2
		  unit 20 Out
		    in  0 843934 3.02999e+08 9.14995e+10 -5.42883 515.506 32785.2
		    out
::

Two problems leap out from the trace: first, there are six channels of the output (there should be 1), and second, all the outputs are well outside the audio range -1..1. The first is because we use multichannel expansion to produce an array of Resonz filters, but we don't mix them down into a single channel.

Note that there are no out of range signals prior to each Resonz. Looking at the Resonz inputs, we see that the frequency input is negative, which will blow up most digital filters.

The resonance frequency derives from multiplying an array by a LFNoise1. Tracing back (the red, italicized numbers), the LFNoise1 is outputting a negative number, where we expected it to be 0.5..1.5. But, the mul and add inputs are reversed!

If you look very carefully at the trace, you will see another problem relating to multichannel expansion. The two components of the detuned sawtooth go into alternate Resonz'es, where we expected both to go, combined, into every Resonz. To fix it, the sawtooths need to be mixed as well.
]

@racketblock[
SynthDef(\resonz, { |freq = 440|
	var	sig, ffreq;
	sig = Mix.ar(Saw.ar([freq, freq+1], 0.2));
	ffreq = LFNoise1.kr(2, 0.5, 1);
	Out.ar(0, Mix.ar(Resonz.ar(sig, (800, 1000..1800) * ffreq, 0.1)))
}).send(s);

a = Synth(\resonz);
a.trace;
a.free;
::

]
@section{section}
  Debugging client-to-server communication

Some bugs result from OSC messages to the server being constructed incorrectly. Julian Rohrhuber's DebugNetAddr is a convenient way to capture messages. The class may be downloaded from: http://swiki.hfbk-hamburg.de:8888/MusicTechnology/710 .

To use it, you need to quit the currently running local server, then create a new server using a DebugNetAddr instead of a regular NetAddr. Messages will be dumped into a new document window.

@racketblock[
s.quit;

Server.default = s = Server.new('local-debug', DebugNetAddr("localhost", 57110));
s.boot;
s.makeWindow;		// optional

	latency nil		// these messages get sent on bootup
		[ "/notify", 1 ]

	latency nil
		[ "/g_new", 1 ]

a = { SinOsc.ar(440, 0, 0.4) ! 2 }.play;

	latency nil
		[ "/d_recv", "data[ 290 ]", [ 9, "-1589009783", 1001, 0, 1, 'i_out', 0, 'out', 0 ] ]

a.free;

	latency nil
		[ 11, 1001 ]
::

]
@section{section}
  Debugging client code

SuperCollider does not have a step trace function, which makes debugging on the client side tougher, but not impossible.

@section{subsection}
  Errors

Learning how to read SuperCollider error output is absolutely essential. Error dumps often (though not always) contain a great deal of information: what the action was, which objects are being acted upon, and how the flow of execution reached that point.

See the link::Guides/Understanding-Errors:: help file for a tutorial.

There's also a graphic Inspector for error dumps, which is enabled with the following command:

@racketblock[
Exception.debug = true;		// enable
Exception.debug = false;	// disable
::
In most cases, this will give you more information than a regular error dump. Usually the regular error dump is sufficient. If you are using Environments or prototype-style programming, the graphic inspector is indispensable.

]
@section{subsection}
  Debug output using post statements

The most common approach is to insert statements to print the values of variables and expressions. Since the normal printing methods don't change the value of an expression, they can be placed in the middle of the statement without altering the processing flow. There's no significant difference between:

@racketblock[
if(a > 0) { positive.value(a) };
::
and
]

@racketblock[
if((a > 0).postln) { positive.value(a) };
::

Common methods to use are:
]

@racketblock[
.postln
.postcs		// post the object as a compile string
.debug(caller)	// post the object along with a tag identifying the caller
::

]

@racketblock[
(
var	positiveFunc;
positiveFunc = { |a|
	a.debug('positiveFunc-arg a');
	a*10
};
a = 5;
if (a > 0) { positiveFunc.value(a) };
)

// output:
positiveFunc-arg a: 5
50
::

The caller argument is optional; however, it's very helpful for tracing the origin of erroneous values.

Another advantage of .debug is that it's easier to search for them in your source code and remove them later.

To print multiple values at one time, wrap them in an array before using .debug or .postcs. Note that if any of the array members are collections, postln will hide them behind the class name: "an Array, a Dictionary" etc. Use postcs if you expect to be posting collections.
]

@racketblock[
[val1, val2, val3].debug(\myMethod);
[\callerTag, val1, val2, val3].postcs;
::
By sprinkling these throughout your code, especially at the beginnings of functions or methods, the debugging output can give you a partial trace of which code blocks get visited in what order.

]
@section{subsection}
  dumpBackTrace

If you discover that a particular method or function is being entered but you don't know how it got there, you can use the 
@racketblock[.dumpBackTrace:: method on any object. You'll get what looks like an error dump, but without the error. Execution continues normally after the stack dump.
]

@racketblock[
(
var	positiveFunc;
positiveFunc = { |a|
	a.debug('positiveFunc-arg a');
	a.dumpBackTrace;
	a*10
};
a = 5;
if (a > 0) { positiveFunc.value(a) };
)

// output:
positiveFunc-arg a: 5
CALL STACK:
	< FunctionDef in closed FunctionDef >
		arg a = 5
	< closed FunctionDef >
		var positiveFunc = <instance of Function>
	Interpreter-interpretPrintCmdLine
		arg this = <instance of Interpreter>
		var res = nil
		var func = <instance of Function>
	Process-interpretPrintCmdLine
		arg this = <instance of Main>
50
::
This tells you that the function came from interpreting a closed FunctionDef (automatically created when evaluating a block of code).

In a method definition, it's recommended to use ]

@racketblock[this.dumpBackTrace::; in a free-standing function, there is no "this" so you should pick some arbitrary object.

]
@section{subsection}
  Tracing streams

To see the results of a pattern, use the .trace method. Each output value from the pattern gets posted to the main output.

@racketblock[
s.boot;
SynthDescLib.global.read;

p = Pbind(\degree, Pwalk((0..14), Pstutter(Pwhite(1, 4, inf), Prand(#[-2, -1, 1, 2], inf)), Pseq(#[-1, 1], inf), 0), \delta, 0.25, \sustain, 0.2, \instrument, \default).trace.play;

p.stop;
::

]
@section{subsection}
  Debugging infinite loops or recursion

@racketblock[
while(true);
::
This is a bad idea. It will lock up SuperCollider and you will have to force quit. Sometimes this happens in your code and the reason isn't obvious. Debugging these situations is very painful because you might have to force quit, relaunch SuperCollider, and reload your code just to try again.
]

@racketblock[
f = { |func| func.value(func) };
f.value(f);
::
Infinite recursion, on the other hand, is more likely to cause SuperCollider to quit unexpectedly when the execution stack runs out of space.

In macOS, inserting "post" or "debug" calls will not help with infinite loops or recursion, because posted output is held in a buffer until execution is complete. If execution never completes, you never see the output.

One useful approach is to insert statements that will cause execution to halt. The easiest is .halt, but it provides you with no information about where or how it stopped, or how it got there. If you want a more descriptive message, make up an error and throw it:
]

@racketblock[
Error("myFunction-halt").throw;
::
When debugging code that crashes, place a line like this somewhere in the code. If you get the error output, you know that the infinite loop is happening after the error--so move the error.throw later and try again.
If it crashes, you know the infinite loop is earlier. Eventually, after a lot of heartache, you can zero in on the location.

Here is a rogues' gallery of infinite loop gotchas--things that don't look like infinite loops, but they will kill your code quicker than you can wish you hadn't just pushed the enter key:
]

@racketblock[
i = 0;
while (i < 10) { i.postln; i = i+1 }; 	// crash
::
While loop syntax is different in SuperCollider from C. The above loop means to check whether i < 10 once, at the beginning of the loop, then loop if the value is true. Since the loop condition is evaluated only once, it never changes, so the loop never stops. The loop condition should be written inside a function, to wit:
]

@racketblock[
i = 0;
while { i < 10 } { i.postln; i = i+1 };
::
Routines and empty arrays:
]

@racketblock[
a = Array.new;
r = Routine({
	loop {
		a.do({ |item| item.yield });
	}
});
r.next;	// crash
::
This looks pretty innocent: iterate repeatedly over an array and yield each item successively. But, if the array is empty, the do loop never executes and yield never gets called. So, the outer loop{} runs forever, doing nothing.

Recursion is often used to walk through a tree structure. Tree structures are usually finite--no matter which branch you go down, eventually you will reach the end. If you have a data structure that is self-referential, you can easily get infinite recursion:
]

@racketblock[
a = (1..10);
a.put(5, a);	// now one of the items of a is a itself
a.postcs;		// crash--postcs has to walk through the entire collection, which loops on itself
::
Self-referential data structures are sometimes an indication of poor design. If this is the case, avoid them.
]

@racketblock[
a = 0;
SystemClock.sched(2, { a.postln });	// crashes when scheduler fires the function
::
When a scheduled function executes, if it returns a number, the function will be rescheduled for now + the number. If the number is 0, it is effectively the same as an infinite loop.

To fix it, make sure the function returns a non-number.
]

@racketblock[
a = 0;
SystemClock.sched(2, { a.postln; nil });
::

]
@section{subsection}
  Removing debugging statements

Use formatting to help your eye locate debugging statements when it's time to remove them. SuperCollider code is usually indented. If you write your debugging statements fully left-justified, they're much easier to see.

@racketblock[
a = Array.new;
r = Routine({
	loop {
		"debugging".postln;	// looks like regular code, doesn't stand out
		a.do({ |item| item.yield });
	}
});
r.next;	// crash

// vs:

a = Array.new;
r = Routine({
	loop {
"debugging".postln;	// this obviously sticks out
		a.do({ |item| item.yield });
	}
});
r.next;	// crash
::

]