CheckBadValues should run on the first sample as well

[supercollider.git] / HelpSource / Guides / Debugging-tips.schelp

title:: Debugging tips
summary:: tips on debugging synthdefs, client code and more
categories:: Language, Debugging
related:: Guides/Understanding-Errors

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. 

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 OSCresponderNode as follows:
code::
o = OSCFunc({ |msg| msg.postln }, '/tr', s.addr); 
::
Each line of output is an array with four values: code:: ['/tr', defNode, id (from SendTrig), value (from SendTrig)] ::.

code::
{       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, you can store them in a collection of arrays and differentiate them by assigning different IDs in the SendTrig UGen. 
code::
l = { List.new } ! 2;
o = OSCFunc({ |msg|
                // msg[2] is the index
        l[msg[2]].add(msg[3]);
}, '/tr', s.addr); 

{       var     freq, amp;
        freq = LFNoise0.kr(8, 600, 800);
        amp = LFNoise1.kr(10, 0.5, 0.5);
                // Impulse is needed to trigger the /tr message to be sent
        SendTrig.kr(Impulse.kr(4), 0, freq);
        SendTrig.kr(Impulse.kr(4), 1, amp);
        SinOsc.ar(freq, 0, 0.3) ! 2
}.play;

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

l[0].array.plot // view frequencies
l[1].array.plot // view amps
::

subsection:: Shared controls (Internal server only, control rate only) 

The internal server allocates a number of control buses whose memory addresses are shared with the client. The client can poll these buses without using OSC messages. 

Insert a SharedOut.kr UGen into your synthdef. Then, on the client side, use s.getSharedControl(num) to read the value. If you want to track the value over time, use a routine to poll repeatedly.
code::
{       var     freq;
        freq = LFNoise1.kr(2, 600, 800);
        SharedOut.kr(0, freq);          // no need for Impulse here
        SinOsc.ar(freq, 0, 0.3) ! 2
}.play;

l = List.new;
r = fork { loop { l.add(s.getSharedControl(0)); 0.1.wait } };
r.stop;
l.array.plot;  // to view the results graphically 
::

subsection:: Server-side trace 

The code::/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).
code::
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.
code::
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:: 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.
code::
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:: Debugging client code 
 
SuperCollider does not have a step trace function, which makes debugging on the client side tougher, but not impossible. 

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:
code::
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.

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:
code::
if(a > 0) { positive.value(a) };
::
and
code::
if((a > 0).postln) { positive.value(a) }; 
::

Common methods to use are: 
code::
.postln
.postcs         // post the object as a compile string
.debug(caller)  // post the object along with a tag identifying the caller
::

.debug is defined in the crucial library, so Linux and Windows users may not have access to it. It's used like this:
code::
(
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 debug calls and differentiate them from legitimate postln and postcs calls.

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.
code::
[val1, val2, val3].debug(\myMethod);    // or, for a non-Crucial way:
[\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.

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 code::.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.
code::
(
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 code::this.dumpBackTrace::; in a free-standing function, there is no "this" so you should pick some arbitrary object.

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.
code::
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;
::

subsection:: Debugging infinite loops or recursion
code::
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. 
code::
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 Mac OS X, 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:
code::
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:
code::
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:
code::
i = 0;
while { i < 10 } { i.postln; i = i+1 };
::
Routines and empty arrays:
code::
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:
code::
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.
code::
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.
code::
a = 0;
SystemClock.sched(2, { a.postln; nil });
::

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.
code::
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
::