Debugging regression tests
Posted: Thu Jun 16, 2011 10:37 pm
By Marika's post I became aware that not everybody knows how to debug regression tests. In my opinion it is important to have a standard way to spot what caused the difference. Otherwise you will come in situations where you hunt for the cause for weeks again and again.
I have a class EventLogger:
This class will count calls to next() in s_number and return true on every n-th call, where n is EventLoggerRc::frequency[s_stage].
s_stage starts with 0 and is incremented every time s_number becomes larger than threshold[s_stage].
When the search to examine is short, I just set frequency to 1 and no thresholds.
When the search is larger, I set frequency to 10000 at the beginning. When I see that the difference arose between call 47110000 and 47120000, I have another run with frequency = { 10000, 1, 10000} and threshold = {47110000, 47120000}. This way I see that the last identical output was for call number 47110815. In a third run, I change 1234 to 47110815 and set a breakpoint in function breakpoint(), resulting in a conditional breakpoint where the condition is compiled in. Normal conditional breakpoints are too slow in most cases.
Once the debugger stands at the last identical event of both versions, I step though them in parallel. If the calls to EventLogger are dense enough, I can spot easily where the versions ramify.
I have calls to EventLogger distributed over my code, commented out by macros. I can add calls at more specific positions in both versions, but in most cases it is sufficient to enable the calls that are already there. Calls look like this:
This is a foolproof way to track down differences in any regression tests. It involves dull work, but it is much faster than speculating every time.
Btw. 4711 and 0815 are the German placeholder numbers, just as foobar and John Doe. I don't know about placeholder numbers in other languages.
I have a class EventLogger:
Code: Select all
#ifndef _EVENT_LOGGER_HPP
#define _EVENT_LOGGER_HPP
#include <cstddef>
class EventLogger
{
private:
// index of interval in EventLoggerRc::threshold in that d_number is
static size_t s_stage;
// counter for number of events (calls of next while enabled)
static int s_number;
public:
// notifies logger about new event
// @return should event be logged?
static bool next ();
// number of last event
static int number ();
};
#endif
Code: Select all
#include "event_logger.hpp"
#include "rc_settings.hpp"
// from rc_settings.hpp; provides vector<int>
// with values read from a configuration file
OG_SETTINGS (EventLogger,
(IntVector) (frequency) ("")
(IntVector) (threshold) (""))
static void breakpoint ()
{
// breakpoint in this function will not be "optimized" away
}
size_t EventLogger::s_stage = 0;
int EventLogger::s_number = 0;
bool EventLogger::next ()
{
// count event
++s_number;
if (s_number==1234)
breakpoint();
// go to next stage
if (s_stage < EventLoggerRc::threshold.size()
&& s_number > EventLoggerRc::threshold[s_stage])
{
++s_stage;
}
// compute if to log
return s_stage >= EventLoggerRc::frequency.size()
|| s_number % EventLoggerRc::frequency[s_stage] == 0;
}
int EventLogger::number ()
{
return s_number;
}
This class will count calls to next() in s_number and return true on every n-th call, where n is EventLoggerRc::frequency[s_stage].
s_stage starts with 0 and is incremented every time s_number becomes larger than threshold[s_stage].
When the search to examine is short, I just set frequency to 1 and no thresholds.
When the search is larger, I set frequency to 10000 at the beginning. When I see that the difference arose between call 47110000 and 47120000, I have another run with frequency = { 10000, 1, 10000} and threshold = {47110000, 47120000}. This way I see that the last identical output was for call number 47110815. In a third run, I change 1234 to 47110815 and set a breakpoint in function breakpoint(), resulting in a conditional breakpoint where the condition is compiled in. Normal conditional breakpoints are too slow in most cases.
Once the debugger stands at the last identical event of both versions, I step though them in parallel. If the calls to EventLogger are dense enough, I can spot easily where the versions ramify.
I have calls to EventLogger distributed over my code, commented out by macros. I can add calls at more specific positions in both versions, but in most cases it is sufficient to enable the calls that are already there. Calls look like this:
Code: Select all
#ifdef OG_LOG_BOARD
if (BoardRc::log && v_undo && EventLogger::next())
{
std::cerr << EventLogger::number()
<< " " << g_messenger.rank() << ":" // thread ID
<< " Board::do_move " << p_move
<< std::endl;
}
#endif
Btw. 4711 and 0815 are the German placeholder numbers, just as foobar and John Doe. I don't know about placeholder numbers in other languages.