Commit e8a4036e authored by Wouter Klouwen's avatar Wouter Klouwen
Browse files

CTest: use std::chrono::steady_clock for time keeping

It was reported in issue #17345 that CTest does not use monotonic time
to report test duration. Monotonic clocks are not affected by large NTP
adjustments or things like daylight savings time.

As CMake 3.10 requires C++11, which introduced std::chrono, this commit
moves the time keeping in CTest from cmSystemTools::GetTime() to
std::chrono::steady_clock.

Fixes: #17345
parent b77501d4
......@@ -10,6 +10,7 @@
#include "cmake.h"
#include "cmsys/Process.h"
#include <chrono>
#include <stdlib.h>
cmCTestBuildAndTestHandler::cmCTestBuildAndTestHandler()
......@@ -192,7 +193,7 @@ int cmCTestBuildAndTestHandler::RunCMakeAndTest(std::string* outstring)
// we need to honor the timeout specified, the timeout include cmake, build
// and test time
double clock_start = cmSystemTools::GetTime();
auto clock_start = std::chrono::steady_clock::now();
// make sure the binary dir is there
out << "Internal cmake changing into directory: " << this->BinaryDir
......@@ -222,10 +223,12 @@ int cmCTestBuildAndTestHandler::RunCMakeAndTest(std::string* outstring)
this->BuildTargets.push_back("");
}
for (std::string const& tar : this->BuildTargets) {
double remainingTime = 0;
std::chrono::duration<double> remainingTime = std::chrono::seconds(0);
if (this->Timeout > 0) {
remainingTime = this->Timeout - cmSystemTools::GetTime() + clock_start;
if (remainingTime <= 0) {
remainingTime = std::chrono::duration<double>(this->Timeout) -
std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::steady_clock::now() - clock_start);
if (remainingTime <= std::chrono::seconds(0)) {
if (outstring) {
*outstring = "--build-and-test timeout exceeded. ";
}
......@@ -248,7 +251,7 @@ int cmCTestBuildAndTestHandler::RunCMakeAndTest(std::string* outstring)
int retVal = cm.GetGlobalGenerator()->Build(
this->SourceDir, this->BinaryDir, this->BuildProject, tar, output,
this->BuildMakeProgram, config, !this->BuildNoClean, false, false,
remainingTime);
remainingTime.count());
out << output;
// if the build failed then return
if (retVal) {
......@@ -320,10 +323,12 @@ int cmCTestBuildAndTestHandler::RunCMakeAndTest(std::string* outstring)
out << "\n";
// how much time is remaining
double remainingTime = 0;
std::chrono::duration<double> remainingTime = std::chrono::seconds(0);
if (this->Timeout > 0) {
remainingTime = this->Timeout - cmSystemTools::GetTime() + clock_start;
if (remainingTime <= 0) {
remainingTime = std::chrono::duration<double>(this->Timeout) -
std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::steady_clock::now() - clock_start);
if (remainingTime <= std::chrono::seconds(0)) {
if (outstring) {
*outstring = "--build-and-test timeout exceeded. ";
}
......@@ -332,7 +337,7 @@ int cmCTestBuildAndTestHandler::RunCMakeAndTest(std::string* outstring)
}
int runTestRes = this->CTest->RunTest(testCommand, &outs, &retval, nullptr,
remainingTime, nullptr);
remainingTime.count(), nullptr);
if (runTestRes != cmsysProcess_State_Exited || retval != 0) {
out << "Test command failed: " << testCommand[0] << "\n";
......
......@@ -17,6 +17,7 @@
#include <set>
#include <stdlib.h>
#include <string.h>
#include <type_traits>
static const char* cmCTestErrorMatches[] = {
"^[Bb]us [Ee]rror",
......@@ -327,7 +328,7 @@ int cmCTestBuildHandler::ProcessHandler()
// Create a last build log
cmGeneratedFileStream ofs;
double elapsed_time_start = cmSystemTools::GetTime();
auto elapsed_time_start = std::chrono::steady_clock::now();
if (!this->StartLogFile("Build", ofs)) {
cmCTestLog(this->CTest, ERROR_MESSAGE, "Cannot create build log file"
<< std::endl);
......@@ -421,7 +422,8 @@ int cmCTestBuildHandler::ProcessHandler()
// Remember end build time and calculate elapsed time
this->EndBuild = this->CTest->CurrentTime();
this->EndBuildTime = cmSystemTools::GetTime();
double elapsed_build_time = cmSystemTools::GetTime() - elapsed_time_start;
auto elapsed_build_time =
std::chrono::steady_clock::now() - elapsed_time_start;
// Cleanups strings in the errors and warnings list.
if (!this->SimplifySourceDir.empty()) {
......@@ -633,8 +635,8 @@ void cmCTestBuildHandler::GenerateXMLLogScraped(cmXMLWriter& xml)
}
}
void cmCTestBuildHandler::GenerateXMLFooter(cmXMLWriter& xml,
double elapsed_build_time)
void cmCTestBuildHandler::GenerateXMLFooter(
cmXMLWriter& xml, std::chrono::duration<double> elapsed_build_time)
{
xml.StartElement("Log");
xml.Attribute("Encoding", "base64");
......@@ -643,8 +645,10 @@ void cmCTestBuildHandler::GenerateXMLFooter(cmXMLWriter& xml,
xml.Element("EndDateTime", this->EndBuild);
xml.Element("EndBuildTime", static_cast<unsigned int>(this->EndBuildTime));
xml.Element("ElapsedMinutes",
static_cast<int>(elapsed_build_time / 6) / 10.0);
xml.Element(
"ElapsedMinutes",
std::chrono::duration_cast<std::chrono::minutes>(elapsed_build_time)
.count());
xml.EndElement(); // Build
this->CTest->EndXML(xml);
}
......
......@@ -9,6 +9,7 @@
#include "cmProcessOutput.h"
#include "cmsys/RegularExpression.hxx"
#include <chrono>
#include <deque>
#include <iosfwd>
#include <stddef.h>
......@@ -86,7 +87,8 @@ private:
void GenerateXMLHeader(cmXMLWriter& xml);
void GenerateXMLLaunched(cmXMLWriter& xml);
void GenerateXMLLogScraped(cmXMLWriter& xml);
void GenerateXMLFooter(cmXMLWriter& xml, double elapsed_build_time);
void GenerateXMLFooter(cmXMLWriter& xml,
std::chrono::duration<double> elapsed_build_time);
bool IsLaunchedErrorFile(const char* fname);
bool IsLaunchedWarningFile(const char* fname);
......
......@@ -7,8 +7,10 @@
#include "cmSystemTools.h"
#include "cmXMLWriter.h"
#include <chrono>
#include <ostream>
#include <string>
#include <type_traits>
cmCTestConfigureHandler::cmCTestConfigureHandler()
{
......@@ -43,7 +45,7 @@ int cmCTestConfigureHandler::ProcessHandler()
return -1;
}
double elapsed_time_start = cmSystemTools::GetTime();
auto elapsed_time_start = std::chrono::steady_clock::now();
std::string output;
int retVal = 0;
int res = 0;
......@@ -84,10 +86,10 @@ int cmCTestConfigureHandler::ProcessHandler()
xml.Element("EndDateTime", this->CTest->CurrentTime());
xml.Element("EndConfigureTime",
static_cast<unsigned int>(cmSystemTools::GetTime()));
xml.Element(
"ElapsedMinutes",
static_cast<int>((cmSystemTools::GetTime() - elapsed_time_start) / 6) /
10.0);
xml.Element("ElapsedMinutes",
std::chrono::duration_cast<std::chrono::minutes>(
std::chrono::steady_clock::now() - elapsed_time_start)
.count());
xml.EndElement(); // Configure
this->CTest->EndXML(xml);
}
......
......@@ -21,11 +21,13 @@
#include "cmsys/Process.h"
#include "cmsys/RegularExpression.hxx"
#include <algorithm>
#include <chrono>
#include <iomanip>
#include <iterator>
#include <sstream>
#include <stdio.h>
#include <stdlib.h>
#include <type_traits>
#include <utility>
class cmMakefile;
......@@ -290,13 +292,14 @@ int cmCTestCoverageHandler::ProcessHandler()
this->LoadLabels();
cmGeneratedFileStream ofs;
double elapsed_time_start = cmSystemTools::GetTime();
auto elapsed_time_start = std::chrono::steady_clock::now();
if (!this->StartLogFile("Coverage", ofs)) {
cmCTestLog(this->CTest, ERROR_MESSAGE,
"Cannot create LastCoverage.log file" << std::endl);
}
ofs << "Performing coverage: " << elapsed_time_start << std::endl;
ofs << "Performing coverage: "
<< elapsed_time_start.time_since_epoch().count() << std::endl;
this->CleanCoverageLogFiles(ofs);
cmSystemTools::ConvertToUnixSlashes(sourceDir);
......@@ -621,10 +624,10 @@ int cmCTestCoverageHandler::ProcessHandler()
covSumXML.Element("EndDateTime", end_time);
covSumXML.Element("EndTime",
static_cast<unsigned int>(cmSystemTools::GetTime()));
covSumXML.Element(
"ElapsedMinutes",
static_cast<int>((cmSystemTools::GetTime() - elapsed_time_start) / 6) /
10.0);
covSumXML.Element("ElapsedMinutes",
std::chrono::duration_cast<std::chrono::minutes>(
std::chrono::steady_clock::now() - elapsed_time_start)
.count());
covSumXML.EndElement(); // Coverage
this->CTest->EndXML(covSumXML);
......@@ -1963,7 +1966,7 @@ int cmCTestCoverageHandler::RunBullseyeSourceSummary(
return 0;
}
this->CTest->StartXML(xml, this->AppendXML);
double elapsed_time_start = cmSystemTools::GetTime();
auto elapsed_time_start = std::chrono::steady_clock::now();
std::string coverage_start_time = this->CTest->CurrentTime();
xml.StartElement("Coverage");
xml.Element("StartDateTime", coverage_start_time);
......@@ -2090,10 +2093,10 @@ int cmCTestCoverageHandler::RunBullseyeSourceSummary(
xml.Element("PercentCoverage", SAFEDIV(percent_coverage, number_files));
xml.Element("EndDateTime", end_time);
xml.Element("EndTime", static_cast<unsigned int>(cmSystemTools::GetTime()));
xml.Element(
"ElapsedMinutes",
static_cast<int>((cmSystemTools::GetTime() - elapsed_time_start) / 6) /
10.0);
xml.Element("ElapsedMinutes",
std::chrono::duration_cast<std::chrono::minutes>(
std::chrono::steady_clock::now() - elapsed_time_start)
.count());
xml.EndElement(); // Coverage
this->CTest->EndXML(xml);
......
......@@ -10,9 +10,11 @@
#include "cmsys/FStream.hxx"
#include "cmsys/Glob.hxx"
#include "cmsys/RegularExpression.hxx"
#include <chrono>
#include <iostream>
#include <sstream>
#include <string.h>
#include <type_traits>
struct CatToErrorType
{
......@@ -408,8 +410,10 @@ void cmCTestMemCheckHandler::GenerateDartOutput(cmXMLWriter& xml)
xml.Element("EndDateTime", this->EndTest);
xml.Element("EndTestTime", this->EndTestTime);
xml.Element("ElapsedMinutes",
static_cast<int>(this->ElapsedTestingTime / 6) / 10.0);
xml.Element(
"ElapsedMinutes",
std::chrono::duration_cast<std::chrono::minutes>(this->ElapsedTestingTime)
.count());
xml.EndElement(); // DynamicAnalysis
this->CTest->EndXML(xml);
......@@ -844,7 +848,7 @@ bool cmCTestMemCheckHandler::ProcessMemCheckValgrindOutput(
cmsys::RegularExpression vgABR("== .*pthread_mutex_unlock: mutex is "
"locked by a different thread");
std::vector<std::string::size_type> nonValGrindOutput;
double sttime = cmSystemTools::GetTime();
auto sttime = std::chrono::steady_clock::now();
cmCTestOptionalLog(this->CTest, DEBUG,
"Start test: " << lines.size() << std::endl, this->Quiet);
std::string::size_type totalOutputSize = 0;
......@@ -918,7 +922,10 @@ bool cmCTestMemCheckHandler::ProcessMemCheckValgrindOutput(
}
}
cmCTestOptionalLog(this->CTest, DEBUG, "End test (elapsed: "
<< (cmSystemTools::GetTime() - sttime) << std::endl,
<< std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::steady_clock::now() - sttime)
.count()
<< "s)" << std::endl,
this->Quiet);
log = ostr.str();
this->DefectCount += defects;
......@@ -929,7 +936,7 @@ bool cmCTestMemCheckHandler::ProcessMemCheckBoundsCheckerOutput(
const std::string& str, std::string& log, std::vector<int>& results)
{
log.clear();
double sttime = cmSystemTools::GetTime();
auto sttime = std::chrono::steady_clock::now();
std::vector<std::string> lines;
cmSystemTools::Split(str.c_str(), lines);
cmCTestOptionalLog(this->CTest, DEBUG,
......@@ -961,7 +968,10 @@ bool cmCTestMemCheckHandler::ProcessMemCheckBoundsCheckerOutput(
defects++;
}
cmCTestOptionalLog(this->CTest, DEBUG, "End test (elapsed: "
<< (cmSystemTools::GetTime() - sttime) << std::endl,
<< std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::steady_clock::now() - sttime)
.count()
<< "s)" << std::endl,
this->Quiet);
if (defects) {
// only put the output of Bounds Checker if there were
......
......@@ -14,6 +14,7 @@
#include "cmsys/Base64.h"
#include "cmsys/Process.h"
#include "cmsys/RegularExpression.hxx"
#include <chrono>
#include <iomanip>
#include <sstream>
#include <stdio.h>
......@@ -46,11 +47,12 @@ cmCTestRunTest::~cmCTestRunTest()
bool cmCTestRunTest::CheckOutput()
{
// Read lines for up to 0.1 seconds of total time.
double timeout = 0.1;
double timeEnd = cmSystemTools::GetTime() + timeout;
std::chrono::duration<double> timeout = std::chrono::milliseconds(100);
auto timeEnd = std::chrono::steady_clock::now() + timeout;
std::string line;
while ((timeout = timeEnd - cmSystemTools::GetTime(), timeout > 0)) {
int p = this->TestProcess->GetNextOutputLine(line, timeout);
while ((timeout = timeEnd - std::chrono::steady_clock::now(),
timeout > std::chrono::seconds(0))) {
int p = this->TestProcess->GetNextOutputLine(line, timeout.count());
if (p == cmsysProcess_Pipe_None) {
// Process has terminated and all output read.
return false;
......
......@@ -5,10 +5,12 @@
#include "cmsys/Directory.hxx"
#include "cmsys/Process.h"
#include <map>
#include <ratio>
#include <sstream>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <type_traits>
#include <utility>
#include "cmCTest.h"
......@@ -79,7 +81,7 @@ cmCTestScriptHandler::cmCTestScriptHandler()
this->CMake = nullptr;
this->GlobalGenerator = nullptr;
this->ScriptStartTime = 0;
this->ScriptStartTime = std::chrono::steady_clock::time_point();
// the *60 is because the settings are in minutes but GetTime is seconds
this->MinimumInterval = 30 * 60;
......@@ -111,7 +113,7 @@ void cmCTestScriptHandler::Initialize()
this->ContinuousDuration = -1;
// what time in seconds did this script start running
this->ScriptStartTime = 0;
this->ScriptStartTime = std::chrono::steady_clock::time_point();
delete this->Makefile;
this->Makefile = nullptr;
......@@ -158,11 +160,10 @@ void cmCTestScriptHandler::UpdateElapsedTime()
{
if (this->Makefile) {
// set the current elapsed time
char timeString[20];
int itime = static_cast<unsigned int>(cmSystemTools::GetTime() -
this->ScriptStartTime);
sprintf(timeString, "%i", itime);
this->Makefile->AddDefinition("CTEST_ELAPSED_TIME", timeString);
auto itime = std::chrono::duration_cast<std::chrono::seconds>(
std::chrono::steady_clock::now() - this->ScriptStartTime);
auto timeString = std::to_string(itime.count());
this->Makefile->AddDefinition("CTEST_ELAPSED_TIME", timeString.c_str());
}
}
......@@ -507,7 +508,7 @@ int cmCTestScriptHandler::RunConfigurationScript(
int result;
this->ScriptStartTime = cmSystemTools::GetTime();
this->ScriptStartTime = std::chrono::steady_clock::now();
// read in the script
if (pscope) {
......@@ -558,22 +559,27 @@ int cmCTestScriptHandler::RunCurrentScript()
// for a continuous, do we ned to run it more than once?
if (this->ContinuousDuration >= 0) {
this->UpdateElapsedTime();
double ending_time = cmSystemTools::GetTime() + this->ContinuousDuration;
auto ending_time = std::chrono::steady_clock::now() +
std::chrono::duration<double>(this->ContinuousDuration);
if (this->EmptyBinDirOnce) {
this->EmptyBinDir = true;
}
do {
double interval = cmSystemTools::GetTime();
auto startOfInterval = std::chrono::steady_clock::now();
result = this->RunConfigurationDashboard();
interval = cmSystemTools::GetTime() - interval;
if (interval < this->MinimumInterval) {
this->SleepInSeconds(
static_cast<unsigned int>(this->MinimumInterval - interval));
auto interval = std::chrono::steady_clock::now() - startOfInterval;
auto minimumInterval =
std::chrono::duration<double>(this->MinimumInterval);
if (interval < minimumInterval) {
auto sleepTime = std::chrono::duration_cast<std::chrono::seconds>(
minimumInterval - interval)
.count();
this->SleepInSeconds(static_cast<unsigned int>(sleepTime));
}
if (this->EmptyBinDirOnce) {
this->EmptyBinDir = false;
}
} while (cmSystemTools::GetTime() < ending_time);
} while (std::chrono::steady_clock::now() < ending_time);
}
// otherwise just run it once
else {
......@@ -967,7 +973,9 @@ double cmCTestScriptHandler::GetRemainingTimeAllowed()
return 1.0e7;
}
double timelimit = atof(timelimitS);
auto timelimit = std::chrono::duration<double>(atof(timelimitS));
return timelimit - cmSystemTools::GetTime() + this->ScriptStartTime;
auto duration = std::chrono::duration_cast<std::chrono::duration<double>>(
std::chrono::steady_clock::now() - this->ScriptStartTime);
return (timelimit - duration).count();
}
......@@ -7,6 +7,7 @@
#include "cmCTestGenericHandler.h"
#include <chrono>
#include <string>
#include <vector>
......@@ -104,6 +105,7 @@ public:
void CreateCMake();
cmake* GetCMake() { return this->CMake; }
private:
// reads in a script
int ReadInScript(const std::string& total_script_arg);
......@@ -156,7 +158,7 @@ private:
double ContinuousDuration;
// what time in seconds did this script start running
double ScriptStartTime;
std::chrono::steady_clock::time_point ScriptStartTime;
cmMakefile* Makefile;
cmGlobalGenerator* GlobalGenerator;
......
......@@ -6,6 +6,7 @@
#include "cm_jsoncpp_reader.h"
#include "cm_jsoncpp_value.h"
#include "cmsys/Process.h"
#include <chrono>
#include <sstream>
#include <stdio.h>
#include <stdlib.h>
......@@ -496,10 +497,11 @@ bool cmCTestSubmitHandler::SubmitUsingHTTP(const std::string& localprefix,
? ""
: this->GetOption("RetryCount");
int delay = retryDelay.empty()
? atoi(this->CTest->GetCTestConfiguration("CTestSubmitRetryDelay")
.c_str())
: atoi(retryDelay.c_str());
auto delay = std::chrono::duration<double>(
retryDelay.empty()
? atoi(this->CTest->GetCTestConfiguration("CTestSubmitRetryDelay")
.c_str())
: atoi(retryDelay.c_str()));
int count = retryCount.empty()
? atoi(this->CTest->GetCTestConfiguration("CTestSubmitRetryCount")
.c_str())
......@@ -507,12 +509,12 @@ bool cmCTestSubmitHandler::SubmitUsingHTTP(const std::string& localprefix,
for (int i = 0; i < count; i++) {
cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
" Submit failed, waiting " << delay
" Submit failed, waiting " << delay.count()
<< " seconds...\n",
this->Quiet);
double stop = cmSystemTools::GetTime() + delay;
while (cmSystemTools::GetTime() < stop) {
auto stop = std::chrono::steady_clock::now() + delay;
while (std::chrono::steady_clock::now() < stop) {
cmSystemTools::Delay(100);
}
......@@ -1031,11 +1033,15 @@ int cmCTestSubmitHandler::HandleCDashUploadFile(std::string const& file,
std::string retryCountString = this->GetOption("RetryCount") == nullptr
? ""
: this->GetOption("RetryCount");
unsigned long retryDelay = 0;
auto retryDelay = std::chrono::seconds(0);
if (!retryDelayString.empty()) {
if (!cmSystemTools::StringToULong(retryDelayString.c_str(), &retryDelay)) {
unsigned long retryDelayValue = 0;
if (!cmSystemTools::StringToULong(retryDelayString.c_str(),
&retryDelayValue)) {
cmCTestLog(this->CTest, WARNING, "Invalid value for 'RETRY_DELAY' : "
<< retryDelayString << std::endl);
} else {
retryDelay = std::chrono::seconds(retryDelayValue);
}
}
unsigned long retryCount = 0;
......@@ -1087,12 +1093,12 @@ int cmCTestSubmitHandler::HandleCDashUploadFile(std::string const& file,
// If request failed, wait and retry.
for (unsigned long i = 0; i < retryCount; i++) {
cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
" Request failed, waiting " << retryDelay
" Request failed, waiting " << retryDelay.count()
<< " seconds...\n",
this->Quiet);
double stop = cmSystemTools::GetTime() + static_cast<double>(retryDelay);
while (cmSystemTools::GetTime() < stop) {
auto stop = std::chrono::steady_clock::now() + retryDelay;
while (std::chrono::steady_clock::now() < stop) {
cmSystemTools::Delay(100);
}
......@@ -1161,12 +1167,12 @@ int cmCTestSubmitHandler::HandleCDashUploadFile(std::string const& file,
// If upload failed, wait and retry.
for (unsigned long i = 0; i < retryCount; i++) {
cmCTestOptionalLog(this->CTest, HANDLER_OUTPUT,
" Upload failed, waiting " << retryDelay
" Upload failed, waiting " << retryDelay.count()
<< " seconds...\n",
this->Quiet);
double stop = cmSystemTools::GetTime() + static_cast<double>(retryDelay);
while (cmSystemTools::GetTime() < stop) {
auto stop = std::chrono::steady_clock::now() + retryDelay;
while (std::chrono::steady_clock::now() < stop) {
cmSystemTools::Delay(100);
}
......
......@@ -2,6 +2,7 @@
file Copyright.txt or https://cmake.org/licensing for details. */
#include "cmCTestTestHandler.h"
#include <algorithm>
#include <chrono>
#include <cmsys/Base64.h>
#include <cmsys/Directory.hxx>
#include <cmsys/RegularExpression.hxx>
......@@ -15,6 +16,7 @@
#include <stdlib.h>
#include <string.h>
#include <time.h>
#include <type_traits>
#include "cmAlgorithms.h"
#include "cmCTest.h"
......@@ -346,7 +348,7 @@ void cmCTestTestHandler::Initialize()
{
this->Superclass::Initialize();
this->ElapsedTestingTime = -1;
this->ElapsedTestingTime = std::chrono::duration<double>();
this->TestResults.clear();
......@@ -484,12 +486,11 @@ int cmCTestTestHandler::ProcessHandler()
int total;
// start the real time clock
double clock_start, clock_finish;
clock_start = cmSystemTools::GetTime();
auto clock_start = std::chrono::steady_clock::now();
this->ProcessDirectory(passed, failed);
clock_finish = cmSystemTools::GetTime();
auto clock_finish = std::chrono::steady_clock::now();
total = int(passed.size()) + int(failed.size());
......@@ -540,7 +541,10 @@ int cmCTestTestHandler::ProcessHandler()
this->PrintLabelOrSubprojectSummary(false);
}
char realBuf[1024];
sprintf(realBuf, "%6.2f sec", clock_finish - clock_start);
auto durationInMs = std::chrono::duration_cast<std::chrono::milliseconds>(
clock_finish - clock_start)
.count();
sprintf(realBuf, "%6.2f sec", static_cast<double>(durationInMs) / 1000.0);
cmCTestOptionalLog(this->C