Trace() may not be reliable?

I'm getting weird results when trying to output the bounds of a process block. I assume each block should start exactly where the previous block ended. In Scripter when I try to log these bounds with trace() I always get gaps where the beginning of a process block does not match the end of the previously logged block. There might be something that limits the output capacity of the Trace() function. 

NeedsTimingInfo = true;

function ProcessMIDI() {
var info = GetTimingInfo();
if (info.playing) { 
	Trace("s: " + info.blockStartBeat);
	Trace("e: " + info.blockEndBeat);
}
}

Possible console output on playback:

s: 1
e: 1.011609967549642
s: 1.011609967549642
e: 1.0232199509938558
s: 1.0232199509938558
e: 1.0348299185434977
s: 1.0348299185434977
e: 1.0464399019877115
s: 1.0464399019877115
e: 1.0580498854319254
s: 1.0580498854319254
e: 1.0696598529815673
s: 1.0696598529815673
e: 1.0812698364257813
s: 1.0812698364257813
e: 1.0928798039754233
s: 1.0928798039754233
e: 1.104489787419637
s: 1.104489787419637
e: 1.116099770863851
s: 1.522448968887329
e: 1.5340589523315429
s: 1.5340589523315429
e: 1.545668919881185
s: 1.545668919881185
e: 1.5572789033253986
s: 1.5572789033253986
e: 1.5688888867696127
s: 1.5688888867696127
e: 1.5804988543192544
s: 1.5804988543192544
e: 1.5921088377634685
s: 1.5921088377634685
e: 1.6037188053131104
s: 1.6037188053131104
e: 1.6153287887573242
s: 2.056507921218872
e: 2.0681179046630858
s: 2.0681179046630858
e: 2.0797278881073

In above example there are logs missing between beats 1.116099770863851 and 1.522448968887329, and beats 1.6153287887573242 and 2.056507921218872. However the ProcessMIDI() function seems to work reliably and the timing info object has all the correct information, it's just the Trace() function that sometimes acts lazy.

I've noticed the same thing and most likely its a lazy trace.  The Scripter manual mentions that trace will drop output whenever it feels like it to prioritize midi processing.

One thing you can do is instead of calling trace(), add the info to an array.  Then flush the array during the Idle() function, a few rows at a time.  Then you can verify that processMIDI is always getting called for every block of time.

var NeedsTimingInfo = true;

const MAXFLUSH = 25;
var trace_array = [];

function ProcessMIDI() {
   var info = GetTimingInfo();
   if (info.playing) { 
      trace_array.push("s: " + info.blockStartBeat);
      trace_array.push("e: " + info.blockEndBeat);
      trace_array.push("---");
   }
}

function Idle() {
    var i = 0;
    while( trace_array.length > 0 && i < MAXFLUSH ) {
        Trace(trace_array.shift());
        i++;
    }
}

I've noticed the same thing and most likely its a lazy trace.  The Scripter manual mentions that trace will drop output whenever it feels like it to prioritize midi processing.

 

One thing you can do is instead of calling trace(), add the info to an array.  Then flush the array during the Idle() function, a few rows at a time.  Then you can verify that processMIDI is always getting called for every block of time.

var NeedsTimingInfo = true;

const MAXFLUSH = 25;
var trace_array = [];

function ProcessMIDI() {
   var info = GetTimingInfo();
   if (info.playing) { 
      trace_array.push("s: " + info.blockStartBeat);
      trace_array.push("e: " + info.blockEndBeat);
      trace_array.push("---");
   }
}

function Idle() {
    var i = 0;
    while( trace_array.length > 0 && i < MAXFLUSH ) {
        Trace(trace_array.shift());
        i++;
    }
}

Oh, it says it in the manual? I haven't read it all the way through yet, cause I just started studying the scripter API few days ago. Maybe I was a bit too hasty to share this. But yeah, I thought of storing the logs in a variable to be flushed less frequently, but I wasn't aware of the Idle() function. Thanks for the tip, I'll look into it. 

Unfortunately Trace is unreliable. The only workaround I keep to is the informal rule of keeping messages short and infrequent.

Strings with more than 256 bytes seem to cause an internal buffer overrun and Trace stalls. Trace also stalls when it is called to frequently. ProcessMIDI can be invoked every 2.902 ms when the sample rate is 44.1kHz which may also be a factor.

@Dewdman42's buffering strategy is logically sound, but again, Trace can be unpredictable. I hate saying this, but you may have to implement some kind of rate limiting or use the buffering strategy above and do some analytics in Idle to get the detail you are hoping for. 

// untested example
var LIMIT = 500 // tune as needed
var COUNT = 0
function ProcessMIDI () {
   if (++COUNT === LIMIT) {
       COUNT = 0
       Trace("Message")
   }
}

Idle is called every ~250ms. It would slow down the rate of using Trace to log timingInfo/host state , but unfortunately calls to GetTimingInfo fail in Idle.

Scripter quirks can be a right PIA.