/**
* Starts the launch2FocusLock trace.
*/
void Launch2FocusLock::start(void)
{
if (gLaunch2FocusLock.isRequested()) {
gLaunch2FocusLock.formattedTrace("Launch2FocusLock", __FUNCTION__);
gLaunch2FocusLock.start();
}
}
/**
* Stop the performance tracer.
*/
void PnPBreakdown::stop(void)
{
if (gPnPBreakdown.isRunning()) {
gPnPBreakdown.formattedTrace("PnPBreakdown", __FUNCTION__);
gPnPBreakdown.stop();
}
}
/**
* Start the log breakdown performance tracer.
*/
void PnPBreakdown::start(void)
{
if (gPnPBreakdown.isRequested()) {
gPnPBreakdown.formattedTrace("PnPBreakdown", __FUNCTION__);
gPnPBreakdown.start();
}
}
IOBreakdown::~IOBreakdown()
{
char memData[MEM_DATA_LEN]={0};
if (!mNote)
mNote = "";
if (mMemInfoEnabled) {
mMemMutex.lock();
if (mDbgFD < 0) {
LOGD("dgbopt isn't opened.");
} else {
::write(mDbgFD, DBG_CTRL, 3);
if (mPipeFD < 0) {
LOGD("trace_pipe isn't opened.");
} else {
int n;
do {
n = ::read(mPipeFD, memData, MEM_DATA_LEN - 1);
}while (n<=0);
LOGD("memory <%s,%d>:%s", mNote, n, memData);
}
}
mMemMutex.unlock();
}
LOGD("IOBreakdown-step %s:%s, Time: %lld us, Diff: %lld us",
mFuncName, mNote, gIOBreakdown.timeUs(), gIOBreakdown.lastTimeUs());
}
void TaskQueue::update(float maxTime)
{
PerformanceTimer timer;
timer.start();
TaskRequest *req;
resultQLock.enter();
while (!resultQ.empty() && (maxTime==0 || timer.getSplitTime() < maxTime))
{
req=resultQ.back();
resultQ.pop_back();
--numResults;
--sm_iTotalNumResults;
resultQLock.leave();
if (req->mainThreadFinish())
{
req->mainThreadOnComplete();
delete req;
}
else
{
// if Finish() returns false, more worker thread processing is needed
asyncRequest(req);
}
resultQLock.enter();
}
resultQLock.leave();
}
void GLVSyncTestRenderer::draw(QPainter* painter, QPaintEvent* /*event*/) {
PerformanceTimer timer;
//int t5, t6, t7, t8, t9, t10, t11, t12, t13;
timer.start();
TrackPointer pTrack = m_waveformRenderer->getTrackInfo();
if (!pTrack) {
return;
}
ConstWaveformPointer waveform = pTrack->getWaveform();
if (waveform.isNull()) {
return;
}
const int dataSize = waveform->getDataSize();
if (dataSize <= 1) {
return;
}
const WaveformData* data = waveform->data();
if (data == NULL) {
return;
}
double firstVisualIndex = m_waveformRenderer->getFirstDisplayedPosition() * dataSize;
double lastVisualIndex = m_waveformRenderer->getLastDisplayedPosition() * dataSize;
const int firstIndex = int(firstVisualIndex + 0.5);
firstVisualIndex = firstIndex - firstIndex % 2;
const int lastIndex = int(lastVisualIndex + 0.5);
lastVisualIndex = lastIndex + lastIndex % 2;
//t5 = timer.restart(); // 910
// Reset device for native painting
painter->beginNativePainting();
//t6 = timer.restart(); // 29,150
glEnable(GL_BLEND);
glBlendFunc(GL_SRC_ALPHA, GL_ONE_MINUS_SRC_ALPHA);
// Removed Unsupported OpenGL functions, so that Mixxx can run on OpenGL-ES systems -- amvanbaren 9/2015
// TODO(XXX) Rewrite OpenGL code in glvsynctestrenderer.cpp to support
// the new OpenGL syntax or use Qt instead
//t12 = timer.restart(); // 22,426
painter->endNativePainting();
//t13 = timer.restart(); // 1,430
//qDebug() << t5 << t6 << t7 << t8 << t9 << t10 << t11 << t12 << t13;
//qDebug() << timer.restart(); // 129,498
}
/**
* Starts the AAAprofiler trace.
*/
void AAAProfiler::start(void)
{
if (gAAAProfiler.isRequested()) {
gAAAProfiler.formattedTrace("gAAAProfiler", __FUNCTION__);
gAAAProfiler.start();
}
}
/**
* Stops the AAAprofiler trace and prints out results.
*/
void AAAProfiler::stop(void)
{
if (gAAAProfiler.isRunning()) {
LOGD("3A profiling time::\t%lldms\n",
gAAAProfiler.timeUs() / 1000);
gAAAProfiler.stop();
}
}
/**
* Starts shot2shot trace
*/
void Shot2Shot::start(void)
{
if (gShot2Shot.isRequested()) {
gShot2Shot.start();
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Shot2Shot::start");
}
}
/**
* Starts the FaceLock trace.
*/
void FaceLock::start(int frameNum)
{
if (gFaceLock.isRequested() && !gFaceLock.isRunning()) {
gFaceLock.formattedTrace("FaceLock", __FUNCTION__);
gFaceLockFrame = frameNum;
gFaceLock.start();
}
}
/**
* Starts the launch2preview trace.
*/
void Launch2Preview::start(void)
{
if (gLaunch2Preview.isRequested()) {
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Launch2Preview::start");
gLaunch2Preview.start();
}
}
/**
* Stops the FaceLock trace and prints out results.
*/
void FaceLock::stop(int mFaceNum)
{
if (gFaceLock.isRunning()) {
LOGD("FaceLock face num: %d , Need frame: %d , From preview frame got to face lock successfully:\t%lld ms\n",
mFaceNum, gFaceLockFrame, gFaceLock.timeUs() / 1000);
gFaceLock.mRequested = false;
gFaceLock.stop();
}
}
/**
* To indicate the performance and memory for every IOCTL call.
*
* @arg func, the function name which called it.
* @arg note, a string printed with IOCTL information.
*/
IOBreakdown::IOBreakdown(const char *func, const char *note):
mFuncName(func)
,mNote(note)
{
if (gIOBreakdown.isRunning()) {
gIOBreakdown.timeUs();
gIOBreakdown.lastTimeUs();
}
}
void Shot2Shot::stop(void)
{
if (gShot2Shot.isRunning()) {
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Shot2Shot::stop");
LOGD("shot2shot latency: %lld us.", gShot2Shot.timeUs());
gShot2Shot.stop();
}
}
void HDRShot2Preview::stop(void)
{
if (gHDRShot2Preview.isRunning() && gHDRCalled) {
gHDRCalled = false;
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("HDRShot2Preview::stop");
LOGD("hdr shot2preview latency: %lld us", gHDRShot2Preview.timeUs());
gHDRShot2Preview.stop();
}
}
void ServerPathBuildManager::update ( float timeBudget )
{
PerformanceTimer timer;
timer.start();
updateQueue( &gs_highQueue, timer, timeBudget );
updateQueue( &gs_lowQueue, timer, timeBudget );
}
/**
* Stops the launch2FocusLock trace and prints out results.
*/
void Launch2FocusLock::stop(void)
{
if (gLaunch2FocusLock.isRunning()) {
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Launch2FocusLock::stop");
LOGD("LAUNCH time calculated from create instance to lock the focus frame:\t%lld ms\n",
gLaunch2FocusLock.timeUs() / 1000);
gLaunch2FocusLock.stop();
}
}
/**
* Starts the SwitchCameras trace.
*/
void SwitchCameras::start(int cameraid)
{
if (gSwitchCameras.isRequested()) {
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Switch::start");
gSwitchCamerasCalled = false;
gSwitchCamerasOriginalVideoMode = false;
gSwitchCamerasVideoMode = false;
gSwitchCamerasOriginalCameraId = cameraid;
gSwitchCameras.start();
}
}
bool TestManager::runTestsWithFilter(const std::string & incl, const std::string & excl)
{
// Keep current assertion handler and setup ours
setupAssertionHandler();
setupLogCapturingHandler();
// Prepare tags for filtering
auto included_tags = detail::SplitString(incl, ' ');
auto excluded_tags = detail::SplitString(excl, ' ');
_test_log.clearLogData();
logHeader("== " + _test_manager_name + " Unit Tests Log");
if (included_tags.size() > 0 || excluded_tags.size() > 0) {
if (included_tags.size()) {
logMessage(detail::FormattedString(" * included tags : %s", incl.c_str()));
}
if (excluded_tags.size()) {
logMessage(detail::FormattedString(" * excluded tags : %s", excl.c_str()));
}
logSeparator();
}
bool tests_result = true;
double elapsed_time = 0.0;
if (_registered_tests.size() > 0) {
//
PerformanceTimer timer;
tests_result = executeFilteredTests(included_tags, excluded_tags);
elapsed_time = timer.elapsedTime();
//
} else {
//
logMessage("WARNING: There's no registered test!");
//
}
// Keep elapsed time & report results to log
tl().setElapsedTime(elapsed_time);
TestLogData::Counters log_data_counters = tl().logDataCounters();
logHeader(detail::FormattedString("== RESULTS: %d passed, %d failed, %d skipped, time %s",
log_data_counters.passed_tests,
log_data_counters.failed_tests,
log_data_counters.skipped_tests,
PerformanceTimer::humanReadableTime(elapsed_time).c_str()));
// Set previous assertion handler back
restoreLogCapturingHandler();
restoreAssertionHandler();
return tests_result;
}
/**
* Mark an intermediate step in breakdown tracer.
*
* @arg func, the function name which called it.
* @arg not, a string printed with the breakdown trace
* @arg mFrameNum, the num of the frame got from ISP.
*/
void PnPBreakdown::step(const char *func, const char* note, const int mFrameNum)
{
if (gPnPBreakdown.isRunning()) {
if (!note)
note = "";
if (mFrameNum < 0)
LOGD("PnPBreakdown-step %s:%s, Time: %lld us, Diff: %lld us",
func, note, gPnPBreakdown.timeUs(), gPnPBreakdown.lastTimeUs());
else
LOGD("PnPBreakdown-step %s:%s[%d], Time: %lld us, Diff: %lld us",
func, note, mFrameNum, gPnPBreakdown.timeUs(), gPnPBreakdown.lastTimeUs());
}
}
OsFile::~OsFile()
{
#ifdef _DEBUG
PerformanceTimer t;
t.start();
#endif
CloseHandle(m_handle);
#ifdef _DEBUG
t.stop();
ms_time+= t.getElapsedTime();
#endif
}
mixxx::Duration GLRGBWaveformWidget::render() {
PerformanceTimer timer;
mixxx::Duration t1;
//mixxx::Duration t2, t3;
timer.start();
// QPainter makes QGLContext::currentContext() == context()
// this may delayed until previous buffer swap finished
QPainter painter(this);
t1 = timer.restart();
draw(&painter, NULL);
//t2 = timer.restart();
//qDebug() << "GLRGBWaveformWidget" << t1 << t2;
return t1; // return timer for painter setup
}
// static
qint64 EngineNetworkStream::getNetworkTimeUs() {
// This matches the GPL2 implementation found in
// https://github.com/codders/libshout/blob/a17fb84671d3732317b0353d7281cc47e2df6cf6/src/timing/timing.c
// Instead of ms resolution we use a us resolution to allow low latency settings
// will overflow > 200,000 years
#ifdef __WINDOWS__
FILETIME ft;
qint64 t;
// no GetSystemTimePreciseAsFileTime available, fall
// back to GetSystemTimeAsFileTime. This happens before
// Windows 8 and Windows Server 2012
// GetSystemTime?AsFileTime is NTP adjusted
// QueryPerformanceCounter depends on the CPU crystal
if(s_pfpgGetSystemTimeFn) {
s_pfpgGetSystemTimeFn(&ft);
return ((qint64)ft.dwHighDateTime << 32 | ft.dwLowDateTime) / 10;
} else {
static qint64 oldNow = 0;
static qint64 incCount = 0;
static PerformanceTimer timerSinceInc;
GetSystemTimeAsFileTime(&ft);
qint64 now = ((qint64)ft.dwHighDateTime << 32 | ft.dwLowDateTime) / 10;
if (now == oldNow) {
// timer was not incremented since last call (< 15 ms)
// Add time since last function call after last increment
// This reduces the jitter < one call cycle which is sufficient
LARGE_INTEGER li;
now += timerSinceInc.elapsed().toIntegerMicros();
} else {
// timer was incremented
LARGE_INTEGER li;
timerSinceInc.start();
oldNow = now;
}
return now;
}
#elif defined(__APPLE__)
// clock_gettime is not implemented on OSX
// gettimeofday can go backward due to NTP adjusting
// this will work here, because we take the stream start time for reference
struct timeval mtv;
gettimeofday(&mtv, NULL);
return (qint64)(mtv.tv_sec) * 1000000 + mtv.tv_usec;
#else
// CLOCK_MONOTONIC is NTP adjusted
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return ts.tv_sec * 1000000LL + ts.tv_nsec / 1000;
#endif
}
bool TestManager::executeTest(UnitTestCreationInfo ti, const std::string & full_test_desc)
{
bool test_result = false;
detail::UnitTestFactoryFunction test_factory = ti->factory;
UnitTest * unit_test = test_factory ? test_factory() : nullptr;
if (unit_test != nullptr) {
std::string begin_message = full_test_desc + " ::: START";
logMessage(begin_message);
// Set indentation and run test
tl().setIndentationLevel(2);
PerformanceTimer timer;
double elapsed_time = 0.0;
try {
test_result = unit_test->runTest(this, &_test_log);
elapsed_time = timer.elapsedTime();
} catch (std::exception & exc) {
std::string message("FAILED: Exception: ");
message.append(exc.what());
logMessage(message);
test_result = false;
} catch (...) {
logMessage(std::string("FAILED: An unknown exception occured."));
test_result = false;
}
// Clear indentation & dump result
tl().setIndentationLevel(0);
std::string end_message = full_test_desc;
if (test_result) {
end_message += " ::: OK ::: " + PerformanceTimer::humanReadableTime(elapsed_time);
} else {
end_message += " ::: FAILED";
}
logMessage(end_message);
logSeparator();
// destroy unit test object
delete unit_test;
} else {
CC7_ASSERT(false, "Unable to create '%s'", full_test_desc.c_str());
}
return test_result;
}
int GLRGBWaveformWidget::render() {
PerformanceTimer timer;
int t1;
//int t2, t3;
timer.start();
// QPainter makes QGLContext::currentContext() == context()
// this may delayed until previous buffer swap finished
QPainter painter(this);
t1 = timer.restart();
draw(&painter, NULL);
//t2 = timer.restart();
// glFinish();
//t3 = timer.restart();
//qDebug() << "GLVSyncTestWidget "<< t1 << t2 << t3;
return t1 / 1000; // return timer for painter setup
}
// Returns global high-resolution application timer in seconds.
double Timer::GetSeconds()
{
if(useFakeSeconds)
return FakeSeconds;
return Win32_PerfTimer.GetTimeSecondsDouble();
}
// Delegate to PerformanceTimer.
uint64_t Timer::GetTicksNanos()
{
if (useFakeSeconds)
return (uint64_t) (FakeSeconds * NanosPerSecond);
return Win32_PerfTimer.GetTimeNanos();
}
/**
* Stops the launch2preview trace and prints out results.
*/
void Launch2Preview::stop(int mFrameNum)
{
if (gLaunch2Preview.isRunning()) {
if (gPnPBreakdown.isRunning())
PnPBreakdown::step("Launch2Preview::stop");
if (mFrameNum == 1) {
LOGD("LAUNCH time to the 1st preview frame show:\t%lld ms\n",
gLaunch2Preview.timeUs() / 1000);
} else {
LOGD("LAUNCH: skip %d frame, time to the 1st preview frame show:\t%lld ms\n",
(mFrameNum - 1), gLaunch2Preview.timeUs() / 1000);
}
gLaunch2Preview.stop();
}
}
/**
* Marks that take picture call has been issued.
*
* This is needed to reliably detect start and end of shot2shot
* sequences.
*/
void Shot2Shot::takePictureCalled(void)
{
if (gShot2Shot.isRunning() == true)
stop();
start();
}
/**
* This function will be called at the time of start preview.
*/
void SwitchCameras::called(bool videomode)
{
if (gSwitchCameras.isRequested()) {
gSwitchCamerasCalled = true;
gSwitchCamerasVideoMode = videomode;
}
}
