Hi everybody,
I am currently chasing down some drop outs which occur in my plugin although the CPU meter averages at 20%.
I am using the time profiler from Instruments and it works ok to show me the average cpu usage of every function. But are there some tricks to get the peak usage (something like “only give me the function call that lasted longer than the buffer size”)? They occur only every 20 seconds so they are kind of hard to track down…
In Tracktion we use a trick where we have a class called a GlitchDetector, which is a simple RAII class that measures the time spent while it’s in scope, and asserts if it lives for more than a few milliseconds.
Using a macro, we’ve scattered these in all the audio thread functions where a spike might occur, and although it’s normally disabled in a release build, we can turn them on or add more of them if we’re trying to track down a glitch. Very handy.
Hi Jules,
Interesting trick! Do you think that works reliably in a debug build? Doesn’t it need something that works in a development-release (profiling) build but is disabled in a deployment-release build?
(For example, in a sampler-type plugin I’ve found that some of the logic in controlling voice allocation can be “slow” in a debug build that is optimised away in release.)
Damn, that’s handy. Do you keep any information (something like a static pointer) to the most recent positive GlitchDetector around to avoid getting many assertions down the stack trace?
I think I have some scattering to do 
@martin, I think you can use it with your release build and ifdef it to void before you build the deployment version:
#if CATCH_GLITCH
#define ADD_GLITCH_DETECTOR(name){ GlitchDetector ge(name);}
#else
#define ADD_GLITCH_DETECTOR(name) {}
#endif
Then in your to be profiled function, just add
ADD_GLITCH_DETECTOR("mySlowFunction");
as first line. I’ll write one myself and share it (it seems to be trivial), unless Jules want to migrate this class to JUCE (hint, hint)…
BTW, what is the most recommended function to get a reasonable accurate time vs. performance for measuring in the audio thread (and not only for debugging but in production code that has a CPU meter)?
I am using the following code (this is rather legacy code that was written two years ago):
Time::highResolutionTicksToSeconds(Time::getHighResolutionTicks());
but there are many other functions in the Time class which practically do the same but with different accuracy. I am guessing
static double Time::getMillisecondCounterHiRes()
does the same thing?
Alright, here is my shot:
/** A small helper class that detects a timeout.
*
* Use this to catch down drop outs by adding it to time critical functions in the audio thread and set a global time out value
* using either setMaxMilliSeconds() or, more convenient, setMaxTimeOutFromBufferSize().
*
* Then in your function create a object of this class on the stack and when it is destroyed after the function terminates it
* measures the lifespan of the object and logs to the current system Logger if it exceeds the timespan.
*
* The Identifier you pass in should be unique. It will be used to deactivate logging until you create a GlitchDetector with the same
* ID again. This makes sure you only get one log per glitch (if you have multiple GlitchDetectors in your stack trace,
* they all would fire if a glitch occurred.
*
* You might want to use the macro ADD_GLITCH_DETECTOR(name) (where name is a simple C string literal which will be parsed to a
* static Identifier, because it can be excluded for deployment builds using
*
* #define USE_GLITCH_DETECTION 0
*
* This macro can be only used once per function scope, but this should be OK...
*/
class ScopedGlitchDetector
{
public:
/** Creates a new GlitchDetector with a given identifier.
*
* It uses the id to only log the last call in a stack trace, so you only get the GlitchDetector where the glitch actually occured.
*/
ScopedGlitchDetector(const Identifier &id):
identifier(id),
startTime(Time::getMillisecondCounterHiRes())
{
if(lastPositiveId == id)
{
// Resets the identifier if a GlitchDetector is recreated...
lastPositiveId = Identifier::null;
}
};
~ScopedGlitchDetector()
{
const double stopTime = Time::getMillisecondCounterHiRes();
const double interval = (stopTime - startTime);
if (lastPositiveId.isNull() && interval > maxMilliSeconds)
{
lastPositiveId = identifier;
if(Logger::getCurrentLogger() != nullptr)
{
Logger::getCurrentLogger()->writeToLog("Time out in function: " + identifier.toString());
}
}
}
// =================================================================================================================================
/** Change the global time out value. */
static void setMaxMilliSeconds(double newMaxMilliSeconds) noexcept
{
maxMilliSeconds = newMaxMilliSeconds;
};
/** Same as setMaxMilliSeconds, but accepts the sample rate and the buffer size as parameters to save you some calculation. */
static void setMaxTimeOutFromBufferSize(double sampleRate, double bufferSize) noexcept
{
maxMilliSeconds = (bufferSize / sampleRate) * 1000.0;
};
private:
// =================================================================================================================================
const Identifier identifier;
const double startTime;
static double maxMilliSeconds;
static Identifier lastPositiveId;
// =================================================================================================================================
JUCE_DECLARE_NON_COPYABLE_WITH_LEAK_DETECTOR(ScopedGlitchDetector)
};
#define USE_GLITCH_DETECTION 1
#if USE_GLITCH_DETECTION
#define ADD_GLITCH_DETECTOR(x) static Identifier glitchId(x); ScopedGlitchDetector sgd(glitchId)
#else
#define ADD_GLITCH_DETECTOR(x)
#endif
// Drop these somewhere in a source file (not a header) to avoid duplicate symbols...
double ScopedGlitchDetector::maxMilliSeconds = 3.0;
Identifier ScopedGlitchDetector::lastPositiveId = Identifier();
Feedback is welcome
That’s actually a lot more complex than the one we use, but basically the same idea. We never added anything to make it log any glitches, we only use it for our own debugging/testing, not wanting the extra overhead in a release build, but it might make sense in your app.
In debug mode it can throw a few false positives, but that’s not a big deal, and it’s a handy safeguard to catch occasional mistakes that creep in.
Well, if you #define USE_GLITCH_DETECTION 0, it won’t waste any cycles because it expands the macro ADD_GLITCH_DETECTION() to void.
You could also use this with some kind of singleton TimingStatistics class where your ScopedGlitchDetector destructor adds its measured interval together with the Identifier you supplied.
That class then keeps a simple running average, minimum, maximum and standard deviation for each of the identifiers you supplied (calculation must be kept minimal of course, so i guess keeping a running histogram would be a bit too much).
This way you could also get a view on the timing behavior of each of the identified functions, and not just an assert when something passes a threshold.
Hmmm, I guess that’s what the IDE profiler already does too 
I wanted to add a settable threshold level so you can make it fire when it takes eg 80% of the available time (because chances are great you will get a drop out too) You can then set it to a low value and subclass you StatisticsCounter from Logger without having to change too much. However this class is not supposed to be a good starting point for an all purpose profiler but rather to catch the nasty edge cases that produce clicks…
A slightly modified version of your code with a breakdown of what’s been changed:
Error Handling: The addition of the ErrorHandler class allows for more flexible and customizable error handling. The handleTimeout function can be overridden in a derived class to provide custom behavior when a timeout is detected. This is a significant enhancement as it allows the user to decide what action to take when a glitch is detected.
Logging: The code now includes more logging, which can be helpful for debugging. It logs the creation and destruction of each GlitchDetector object, and when a timeout is detected. This can be useful for tracking the behavior of the program and identifying where glitches are occurring.
Passing identifier by reference: The identifier is now passed by reference to the GlitchDetector constructor, which will be more efficient than passing it by value, especially if Identifier objects are large.
Setting Timeout Duration: The class now includes a method setMaxMilliseconds to set the maximum duration that a function should take to execute, allowing the user to adjust this parameter as needed. Similarly, setMaxTimeOutFromBufferSize allows setting the timeout based on a buffer size and sample rate.
Thread Safety: The use of std::mutex and std::lock_guard provides thread safety for shared data (lastPositiveId, maxMilliseconds, and errorHandler). This prevents race conditions when multiple threads access or modify these shared variables.
Error Handler Ownership: The errorHandler is now a std::shared_ptr<ErrorHandler>, which automatically manages the memory of the errorHandler. This prevents undefined behavior if the errorHandler is deleted while still in use by GlitchDetector.
7 Static Members: The maxMilliseconds, lastPositiveId, and errorHandler are no longer static members. This allows each instance of GlitchDetector to have its own timeout duration, last positive id, and error handler.
8 Reentrancy: The constructor of GlitchDetector now checks if lastPositiveId is already set to the current identifier before resetting it. This prevents the lastPositiveId from being reset when a function with a GlitchDetector is called recursively.
Usage instructions:
#include "GlitchDetector.h": This line should be placed at the top of your .cpp file. It includes the header file GlitchDetector.h which contains the declaration of the GlitchDetector class. Including this file allows you to create GlitchDetector objects in your .cpp file.
#define USE_GLITCH_DETECTION 1: This line defines a macro USE_GLITCH_DETECTION and sets its value to 1. This macro is used as a flag to control whether glitch detection is enabled or not. If USE_GLITCH_DETECTION is 1, the ADD_GLITCH_DETECTOR(x) macro is defined as static Identifier glitchId(x); GlitchDetector glitchDetector(glitchId), which creates a GlitchDetector object when used in your code. If USE_GLITCH_DETECTION is not 1, the ADD_GLITCH_DETECTOR(x) macro is defined as an empty statement, so it doesn’t do anything when used in your code.
#pragma once
#include <mutex>
#include <memory>
class ErrorHandler
{
public:
virtual ~ErrorHandler() {}
virtual void handleTimeout(const String& functionName) = 0;
};
class GlitchDetector
{
public:
GlitchDetector(const Identifier& id) : identifier(id), startTime(Time::getMillisecondCounterHiRes())
{
std::lock_guard<std::mutex> lock(mutex);
if (lastPositiveId == id)
{
// Resets the identifier if a GlitchDetector is recreated...
return;
}
if (Logger::getCurrentLogger() != nullptr)
{
Logger::getCurrentLogger()->writeToLog("GlitchDetector created for: " + identifier.toString());
}
}
~GlitchDetector()
{
std::lock_guard<std::mutex> lock(mutex);
const double stopTime = Time::getMillisecondCounterHiRes();
const double interval = (stopTime - startTime);
if (lastPositiveId.isNull() && interval > maxMilliseconds)
{
lastPositiveId = identifier;
if (Logger::getCurrentLogger() != nullptr)
{
Logger::getCurrentLogger()->writeToLog("Timeout in function: " + identifier.toString());
}
if (errorHandler != nullptr)
{
errorHandler->handleTimeout(identifier.toString());
}
}
if (Logger::getCurrentLogger() != nullptr)
{
Logger::getCurrentLogger()->writeToLog("GlitchDetector destroyed for: " + identifier.toString());
}
}
static void setMaxMilliseconds(double newMaxMilliseconds) noexcept
{
std::lock_guard<std::mutex> lock(mutex);
maxMilliseconds = newMaxMilliseconds;
}
static void setMaxTimeOutFromBufferSize(double sampleRate, int bufferSize) noexcept
{
double maxTimeOut = static_cast<double>(bufferSize) / sampleRate * 1000.0;
setMaxMilliseconds(maxTimeOut);
}
static void setErrorHandler(std::shared_ptr<ErrorHandler> handler) noexcept
{
std::lock_guard<std::mutex> lock(mutex);
errorHandler = handler;
}
private:
const Identifier identifier;
const double startTime;
static double maxMilliseconds;
static Identifier lastPositiveId;
static std::shared_ptr<ErrorHandler> errorHandler;
static std::mutex mutex;
JUCE_DECLARE_NON_COPYABLE_WITH_LEAK_DETECTOR(GlitchDetector)
};
double GlitchDetector::maxMilliseconds = 3.0;
Identifier GlitchDetector::lastPositiveId = Identifier();
std::shared_ptr<ErrorHandler> GlitchDetector::errorHandler = nullptr;
std::mutex GlitchDetector::mutex;
#define USE_GLITCH_DETECTION 1
#if USE_GLITCH_DETECTION
#define ADD_GLITCH_DETECTOR(x) static Identifier glitchId(x); GlitchDetector glitchDetector(glitchId)
#else
#define ADD_GLITCH_DETECTOR(x)
#endif
Interesting! But won’t std::mutex introduce glitches itself?
