// $Id: dynatracer.cpp,v 1.10 2011/03/07 06:08:47 bobgian Exp $ /* * Copyright 2009-2010 Bob Giansiracusa, Mary Kuhner, Jon Yamato, and Joseph Felsenstein * * This software is distributed free of charge for non-commercial use * and is copyrighted. Of course, we do not guarantee that the software * works, and are not responsible for any damage you may cause or have. */ // The name of this file should be changed to "dynameter.cpp", but CVS makes that *so* difficult ... //------------------------------------------------------------------------------------ // If using the Dynameter, must define next symbol before including "local_build.h". // And set its value to start at zero in first user and increase sequentially in each later using file. #define DYNAMETER_FILE_INDEX 0 // Must include next file before testing LAMARC_QA_DYNAMETER and before including "dynatracer.h". #include "local_build.h" #include "dynatracer.h" //------------------------------------------------------------------------------------ // If LAMARC_QA_DYNAMETER is now defined, compile the rest of the file. But if not, skip to the end. // This file is included in the build, but when LAMARC_QA_DYNAMETER is not defined, the rest is skipped // (except for the definition of rdtsc() at the very end). #ifdef LAMARC_QA_DYNAMETER //------------------------------------------------------------------------------------ #include #include #include "timex.h" // for GetTime() using namespace std; //------------------------------------------------------------------------------------ // Experimental overloaded definitions for new and delete. #ifdef LAMARC_QA_MEMORYTRACE // Under construction - not running in current distribution. void * operator new (size_t size) { void * ptr = malloc(size); #ifdef LAMARC_QA_MEMORYPRINT printf("operator new: %lu bytes at %p\n", size, ptr); #endif // LAMARC_QA_MEMORYPRINT if(!ptr) printf("operator new: OUT OF MEMORY\n"); return ptr; } //------------------------------------------------------------------------------------ void * operator new [] (size_t size) { void * ptr = malloc(size); #ifdef LAMARC_QA_MEMORYPRINT printf("operator new []: %lu bytes at %p\n", size, ptr); #endif // LAMARC_QA_MEMORYPRINT if(!ptr) { printf("operator new []: OUT OF MEMORY\n"); } return ptr; } //------------------------------------------------------------------------------------ void operator delete (void * ptr) { #ifdef LAMARC_QA_MEMORYPRINT printf("operator delete: %p\n", ptr); #endif // LAMARC_QA_MEMORYPRINT if(ptr) free(ptr); else printf("operator delete: NULL POINTER\n"); } //------------------------------------------------------------------------------------ void operator delete [] (void * ptr) { #ifdef LAMARC_QA_MEMORYPRINT printf("operator delete []: %p\n", ptr); #endif // LAMARC_QA_MEMORYPRINT if(ptr) free(ptr); else printf("operator delete []: NULL POINTER\n"); } //------------------------------------------------------------------------------------ void operator delete (void * ptr, size_t size) { #ifdef LAMARC_QA_MEMORYPRINT printf("operator delete: %lu bytes at %p\n", size, ptr); #endif // LAMARC_QA_MEMORYPRINT if(ptr) free(ptr); else printf("operator delete: NULL POINTER\n"); } //------------------------------------------------------------------------------------ void operator delete [] (void * ptr, size_t size) { #ifdef LAMARC_QA_MEMORYPRINT printf("operator delete []: %lu bytes at %p\n", size, ptr); #endif // LAMARC_QA_MEMORYPRINT if(ptr) free(ptr); else printf("operator delete []: NULL POINTER\n"); } //------------------------------------------------------------------------------------ void * operator new (size_t size, char * file, unsigned int line) { void * ptr = malloc(size); printf("operator NEW: %lu bytes at %p, File: %s, Line: %u\n", size, ptr, file, line); if(!ptr) printf("operator NEW: OUT OF MEMORY\n"); return ptr; } //------------------------------------------------------------------------------------ void * operator new [] (size_t size, char * file, unsigned int line) { void * ptr = malloc(size); printf("operator NEW []: %lu bytes at %p, File: %s, Line: %u\n", size, ptr, file, line); if(!ptr) printf("operator NEW []: OUT OF MEMORY\n"); return ptr; } #endif // LAMARC_QA_MEMORYTRACE - End of experimental code - not running in current distribution. //------------------------------------------------------------------------------------ // Constructor and expansion of StartDynameter(). LocalDynameter::LocalDynameter(const char * const srcFunctionName, // Supplied by __PRETTY_FUNCTION__ macro const char * const srcFileName, // Supplied by __FILE__ macro const unsigned int srcLineNumber, // Supplied by __LINE__ macro // Next argument supplied by macro expansion as: DYNACOUNTER_START + __COUNTER__ . // DYNACOUNTER_START must be defined at the beginning of each file that uses it // to the starting range of indices for that file to use. Then __COUNTER__ increments // automatically through the range. Count the number of calls in each file so the next // file to use tracing/metering can initialize its range to start with the next value // ( + 1). const unsigned int globalDynameterIdx) : m_fcnEntryTime(rdtsc()), // Clock count at initial function entry. m_srcFunctionName(srcFunctionName), // Function name decorated with class and argument signature. m_srcFileName(srcFileName), // Source file name. #if (LAMARC_QA_DYNAMETER >= 3u) m_tracePrintoutOK(true), // Controls suppression of trace printout (elision). #endif // (LAMARC_QA_DYNAMETER >= 3u) m_calleeRuntime(0u), // Accumulated runtime of callees. m_globalDynameterPtr(NULL), // Pointer to GlobalDynameter object in GlobalDynameterArray. m_srcLineNumber(srcLineNumber) // Source line number. { // Clocks since last clock tracing/metering sample before current call. const unsigned long long int sinceLastBeforeCall = m_fcnEntryTime - s_lastClock; if(s_currentMeterPtr) { // If call to this function was made from another - ie, not the top-level invocation - // set my "parent Meter pointer" to that parent's LocalDynameter object and bump trace level. m_parentMeterPtr = s_currentMeterPtr; #if (LAMARC_QA_DYNAMETER >= 3u) m_tracePrintoutOK = s_currentMeterPtr->m_tracePrintoutOK; m_traceLevel = s_currentMeterPtr->m_traceLevel + 1u; #endif // (LAMARC_QA_DYNAMETER >= 3u) } else { // If this is first call - ie, at toplevel - set a few variables. m_parentMeterPtr = NULL; #if (LAMARC_QA_DYNAMETER >= 3u) m_traceLevel = 0u; cout << "Trace Count Limit (max num calls to same function): "; cin >> s_traceCountLimit; cout << endl; #endif // (LAMARC_QA_DYNAMETER >= 3u) // Set slots of GlobalDynameterArray to NULL here, in case implicit initialization doesn't. for(unsigned int fcn_idx = 0u; fcn_idx < DYNAMETER_ARRAYSIZE; ++fcn_idx) { s_GlobalDynameterArray[fcn_idx] = NULL; } // Print opening trace messages no matter the range to be traced dynamically. s_traceOut.open("TracePrint.out", ios::out); s_traceOut << scientific << setprecision(6); s_traceOut << "Tracing output started: " << PrintTime(GetTime(), "%c") << "\n\nDynameter Version: " << LAMARC_QA_DYNAMETER << "\nCPU_TICKS_PER_SECOND: " << CPU_TICKS_PER_SECOND #if (LAMARC_QA_DYNAMETER >= 3u) << "\nTrace max funcall limit: " << s_traceCountLimit #endif // (LAMARC_QA_DYNAMETER >= 3u) << "\n\nSize of int: " << sizeof(int) << "\nSize of long int: " << sizeof(long int) << "\nSize of long long int: " << sizeof(long long int) << "\nSize of float: " << sizeof(float) << "\nSize of double: " << sizeof(double) << "\nSize of long double: " << sizeof(long double) << "\nSize of int pointer: " << sizeof(int *) << "\nSize of void pointer: " << sizeof(void *) << "\n\n"; } // And set the "global" current Meter Object pointer to ME (ie, I'M the function currently running). s_currentMeterPtr = this; DebugAssert(globalDynameterIdx < DYNAMETER_ARRAYSIZE, "GlobalDynameterArray index overflow"); m_globalDynameterPtr = s_GlobalDynameterArray[globalDynameterIdx]; if(m_globalDynameterPtr) { // If already allocated (second or later call), update these data members. if(sinceLastBeforeCall > m_globalDynameterPtr->m_maxSinceLastBeforeCall) m_globalDynameterPtr->m_maxSinceLastBeforeCall = sinceLastBeforeCall; ++m_globalDynameterPtr->m_selfNumberOfCalls; } else { // If GlobalDynameter object has not yet been allocated and entered into GlobalDynameterArray, do so now. // Note that these objects may be entered into array in non-sequential array index order, // which is why we must keep track of total number as well as NULL/non-NULLness of each entry. // Increment global count of GlobalDynameter objects allocated and use value as fcn's order-of-first-call. m_globalDynameterPtr = new GlobalDynameter(srcFunctionName, srcFileName, ++s_GlobalDynameterCount, 0u, 0u, sinceLastBeforeCall); s_GlobalDynameterArray[globalDynameterIdx] = m_globalDynameterPtr; } // Increment the total number of traced calls so far - used to print total count at end and // (more importantly) to restrict printing of dynamic tracing/metering information to subset of all traced calls. ++s_totalNumberOfCalls; #if (LAMARC_QA_DYNAMETER >= 3u) if(m_tracePrintoutOK && (m_globalDynameterPtr->m_selfNumberOfCalls <= s_traceCountLimit)) { if(s_ellipsisCounter > 0u) print_ellipsis(s_traceOut); print_indentation(s_traceOut); s_traceOut << ">> " << srcFunctionName << " in " << m_srcFileName << ", Line " << srcLineNumber << '\n'; print_indentation(s_traceOut); s_traceOut << "| " << (static_cast(m_fcnEntryTime - s_startClock) / CPU_TICKS_PER_SECOND) << " now. " << (static_cast(sinceLastBeforeCall) / CPU_TICKS_PER_SECOND) << " before. " << m_globalDynameterPtr->m_selfNumberOfCalls << " self, " << s_totalNumberOfCalls << " total.\n"; print_indentation(s_traceOut); s_traceOut << "|\n"; } else { ++s_ellipsisCounter; ++s_printoutsElided; m_tracePrintoutOK = false; } #endif // (LAMARC_QA_DYNAMETER >= 3u) s_lastClock = m_fcnEntryTime; if(sinceLastBeforeCall > s_maxSinceLastBeforeCall) s_maxSinceLastBeforeCall = sinceLastBeforeCall; } //------------------------------------------------------------------------------------ // Destructor. Automatically provides functionality of trace-printing on leaving function. LocalDynameter::~LocalDynameter() { // Set on each call (ie, updated to current time). const unsigned long long int nowClock = rdtsc(); const unsigned long long int myTotalRuntime = nowClock - m_fcnEntryTime; const unsigned long long int mySelfRuntime = myTotalRuntime - m_calleeRuntime; #if (LAMARC_QA_DYNAMETER >= 3u) if(m_tracePrintoutOK && (m_globalDynameterPtr->m_selfNumberOfCalls <= s_traceCountLimit)) { if(s_ellipsisCounter > 0u) { // Trace printout elided last before this call probably was indented one level deeper. ++m_traceLevel; print_ellipsis(s_traceOut); --m_traceLevel; } print_indentation(s_traceOut); // Member variables used since all values printed here must be stored; destructor takes no arguments. s_traceOut << "<< " << m_srcFunctionName << " in " << m_srcFileName << ", Line " << m_srcLineNumber << '\n'; print_indentation(s_traceOut); s_traceOut << " " << (static_cast(nowClock - s_startClock) / CPU_TICKS_PER_SECOND) << " now. " << (static_cast(nowClock - s_lastClock) / CPU_TICKS_PER_SECOND) << " before. " << (static_cast(m_calleeRuntime) / CPU_TICKS_PER_SECOND) << " callees. " << (static_cast(mySelfRuntime) / CPU_TICKS_PER_SECOND) << " self. " << (static_cast(myTotalRuntime) / CPU_TICKS_PER_SECOND) << " total. " << m_globalDynameterPtr->m_selfNumberOfCalls << " self, " << s_totalNumberOfCalls << " total.\n"; print_indentation(s_traceOut); s_traceOut << '\n'; } else { ++s_ellipsisCounter; ++s_printoutsElided; } #endif // (LAMARC_QA_DYNAMETER >= 3u) s_lastClock = nowClock; // Insert the information accumulated in this dynamic object into the permanent structure holding global data. // The GlobalDynameter object is assumed to exist (m_globalDynameterPtr is non-NULL) because otherwise 'new' would // have thrown a 'bad_alloc' exception. m_globalDynameterPtr->m_calleeRuntime += m_calleeRuntime; m_globalDynameterPtr->m_selfRuntime += mySelfRuntime; // Pop the metering tool stack: set current object pointer to my parent. s_currentMeterPtr = m_parentMeterPtr; if(m_parentMeterPtr) { // If parent is non-NULL, increment his kid's runtime by my own. m_parentMeterPtr->m_calleeRuntime += myTotalRuntime; } else { // If we've popped back to top-level, ie, the toplevel destructor, write trailer and close file. // Print closing trace messages no matter the range to be traced dynamically. // First write the summary data stored in the GlobalDynameterArray objects. s_traceOut << "\nTrace information on " << s_GlobalDynameterCount << " functions traced of " << DYNAMETER_ARRAYSIZE << " function slots available.\n"; // "Squish" all populated entries down to contiguous set at "low" end of array. // All functions will have slots reserved at compile time for themselves, but // functions not called during this run will contain empty slots in this array. unsigned int target = 0u, source = 0u; while(source < DYNAMETER_ARRAYSIZE) { if(s_GlobalDynameterArray[source]) // Source populated. { if(s_GlobalDynameterArray[target]) // Source populated; Target populated. { if(source == target) // If tracking same slot, bump both indices. ++source; // Otherwise bump only target. ++target; } else // Source populated; Target empty. { s_GlobalDynameterArray[target] = s_GlobalDynameterArray[source]; // Swap source into target. s_GlobalDynameterArray[source] = NULL; // "Swap" means "clear source slot". ++target; // This pair now OK; bump both indices. ++source; } } else // Source empty; target may be empty or populated. { ++source; // Bump only source (look for populated slot). } DebugAssert(target <= source, "Bug in GlobalDynameterArray squisher"); } DebugAssert((source == DYNAMETER_ARRAYSIZE) && (target == s_GlobalDynameterCount), "Bug in GlobalDynameterArray compactor"); TablePrinter("Traced functions unordered:", "FcnsUnsorted.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, NumSelfCalls); TablePrinter("Traced functions ordered by number of calls:", "FcnsNumCalls.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, MaxSinceLastBefore); TablePrinter("Traced functions ordered by max time since last before call:", "FcnsMaxTimeBefore.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, CalleeRuntimePerCall); TablePrinter("Traced functions ordered by callee runtime per call:", "FcnsCalleeTimePerCall.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, CalleeRuntimeAggregate); TablePrinter("Traced functions ordered by callee runtime, aggregate:", "FcnsCalleeTimeAggregate.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, SelfRuntimePerCall); TablePrinter("Traced functions ordered by self runtime (excluding callees) per call:", "FcnsSelfTimePerCall.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, SelfRuntimeAggregate); TablePrinter("Traced functions ordered by self runtime (excluding callees), aggregate:", "FcnsSelfTimeAggregate.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, TotalRuntimePerCall); TablePrinter("Traced functions ordered by total runtime (self plus callees) per call:", "FcnsTotalTimePerCall.txt"); sort(s_GlobalDynameterArray, s_GlobalDynameterArray + s_GlobalDynameterCount, TotalRuntimeAggregate); TablePrinter("Traced functions ordered by total runtime (self plus callees), aggregate:", "FcnsTotalTimeAggregate.txt"); s_traceOut << "\nTracing output done: " << PrintTime(GetTime(), "%c") << "\nTotal number of calls: " << s_totalNumberOfCalls #if (LAMARC_QA_DYNAMETER >= 3u) << "\nTrace max funcall limit: " << s_traceCountLimit << "\nTrace print calls elided: " << s_printoutsElided #endif // (LAMARC_QA_DYNAMETER >= 3u) << "\n\nDynameter Version: " << LAMARC_QA_DYNAMETER << "\nCPU_TICKS_PER_SECOND: " << CPU_TICKS_PER_SECOND << "\n\nSize of int: " << sizeof(int) << "\nSize of long int: " << sizeof(long int) << "\nSize of long long int: " << sizeof(long long int) << "\nSize of float: " << sizeof(float) << "\nSize of double: " << sizeof(double) << "\nSize of long double: " << sizeof(long double) << "\nSize of int pointer: " << sizeof(int *) << "\nSize of void pointer: " << sizeof(void *) << "\n\nMax since last trace: " << (static_cast(LocalDynameter::s_maxSinceLastBeforeCall) / CPU_TICKS_PER_SECOND) << " sec (over all function calls).\n"; s_traceOut.close(); } } //------------------------------------------------------------------------------------ // Private utility member function. #if (LAMARC_QA_DYNAMETER >= 3u) void LocalDynameter::print_indentation(ofstream & stream) { stream << ' '; for(unsigned int trace_idx = 0u; trace_idx < m_traceLevel; ++trace_idx) stream << "| "; } #endif // (LAMARC_QA_DYNAMETER >= 3u) //------------------------------------------------------------------------------------ // Private utility member function. #if (LAMARC_QA_DYNAMETER >= 3u) void LocalDynameter::print_ellipsis(ofstream & stream) { print_indentation(stream); stream << "... " << s_ellipsisCounter << " trace printouts elided.\n"; print_indentation(stream); stream << '\n'; s_ellipsisCounter = 0u; } #endif // (LAMARC_QA_DYNAMETER >= 3u) //------------------------------------------------------------------------------------ // Private utility member function. void LocalDynameter::TablePrinter(const string heading, const string filename) { ofstream os; os.open(filename.c_str(), ios::out); os << scientific << setprecision(6); os << heading << '\n'; for(unsigned int fcn_idx = 0u; fcn_idx < s_GlobalDynameterCount; ++fcn_idx) { GlobalDynameter * pGlobalDynameter = s_GlobalDynameterArray[fcn_idx]; DebugAssert(pGlobalDynameter, "Bug in GlobalDynameterArray display"); const unsigned long long int selfNumCalls = pGlobalDynameter->m_selfNumberOfCalls; const unsigned long long int calleeRuntime = pGlobalDynameter->m_calleeRuntime; const unsigned long long int selfRuntime = pGlobalDynameter->m_selfRuntime; const unsigned long long int maxSinceLastBeforeCall = pGlobalDynameter->m_maxSinceLastBeforeCall; os << '\n' << fcn_idx << ":\t" << pGlobalDynameter->m_srcFunctionName << " in file " << pGlobalDynameter->m_srcFileName << "\n\t" << selfNumCalls << " calls (order " << pGlobalDynameter->m_ordinalCount << ") " << (static_cast(maxSinceLastBeforeCall) / CPU_TICKS_PER_SECOND) << " before. " << (static_cast(calleeRuntime / selfNumCalls) / CPU_TICKS_PER_SECOND) << '/' << (static_cast(calleeRuntime) / CPU_TICKS_PER_SECOND) << " callees. " << (static_cast(selfRuntime / selfNumCalls) / CPU_TICKS_PER_SECOND) << '/' << (static_cast(selfRuntime) / CPU_TICKS_PER_SECOND) << " self. " << (static_cast((selfRuntime + calleeRuntime) / selfNumCalls) / CPU_TICKS_PER_SECOND) << '/' << (static_cast(selfRuntime + calleeRuntime) / CPU_TICKS_PER_SECOND) << " total.\n"; } os.close(); } //------------------------------------------------------------------------------------ // Constructor for GlobalDynameter called by LocalDynameter constructor to store per-function results. GlobalDynameter::GlobalDynameter(const char * const srcFunctionName, const char * const srcFileName, const unsigned int ordinalCount, const unsigned long long int calleeRuntime, const unsigned long long int selfRuntime, const unsigned long long int maxSinceLastBeforeCall) : m_srcFunctionName(srcFunctionName), // Function name decorated with class and argument signature. m_srcFileName(srcFileName), // Source file name. m_ordinalCount(ordinalCount), // Ordinal count of this function's call of all traced. m_calleeRuntime(calleeRuntime), // Accumulated runtime of callees. m_selfRuntime(selfRuntime), // Accumulated runtime of this function (not including callees). m_maxSinceLastBeforeCall(maxSinceLastBeforeCall), // Max time since last timing measurement (CPU cycles). m_selfNumberOfCalls(1u) // Count of number of times this function called. { } //------------------------------------------------------------------------------------ // Sorts by number of self calls (decreasing order). bool NumSelfCalls(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return x_ptr->m_selfNumberOfCalls > y_ptr->m_selfNumberOfCalls; } //------------------------------------------------------------------------------------ // Sorts by max time since last trace probe before current call (decreasing order). bool MaxSinceLastBefore(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return x_ptr->m_maxSinceLastBeforeCall > y_ptr->m_maxSinceLastBeforeCall; } //------------------------------------------------------------------------------------ // Sorts by callee runtime per call (total over all callees) (decreasing order). bool CalleeRuntimePerCall(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return (x_ptr->m_calleeRuntime / x_ptr->m_selfNumberOfCalls) > (y_ptr->m_calleeRuntime / y_ptr->m_selfNumberOfCalls); } //------------------------------------------------------------------------------------ // Sorts by callee runtime aggregate (summed over all calls) (decreasing order). bool CalleeRuntimeAggregate(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return x_ptr->m_calleeRuntime > y_ptr->m_calleeRuntime; } //------------------------------------------------------------------------------------ // Sorts by self runtime per call (excluding all callees) (decreasing order). bool SelfRuntimePerCall(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return (x_ptr->m_selfRuntime / x_ptr->m_selfNumberOfCalls) > (y_ptr->m_selfRuntime / y_ptr->m_selfNumberOfCalls); } //------------------------------------------------------------------------------------ // Sorts by self runtime aggregate (excluding callees, summed over all calls) (decreasing order). bool SelfRuntimeAggregate(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return x_ptr->m_selfRuntime > y_ptr->m_selfRuntime; } //------------------------------------------------------------------------------------ // Sorts by total runtime per call (sum of self plus callee runtime) (decreasing order). bool TotalRuntimePerCall(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return ((x_ptr->m_selfRuntime + x_ptr->m_calleeRuntime) / x_ptr->m_selfNumberOfCalls) > ((y_ptr->m_selfRuntime + y_ptr->m_calleeRuntime) / y_ptr->m_selfNumberOfCalls); } //------------------------------------------------------------------------------------ // Sorts by total runtime aggregate (self plus callee, summed over all calls) (decreasing order). bool TotalRuntimeAggregate(const GlobalDynameter * const x_ptr, const GlobalDynameter * const y_ptr) { return (x_ptr->m_selfRuntime + x_ptr->m_calleeRuntime) > (y_ptr->m_selfRuntime + y_ptr->m_calleeRuntime); } //------------------------------------------------------------------------------------ #endif // LAMARC_QA_DYNAMETER //------------------------------------------------------------------------------------ // CPU cycle counter used by tracing/metering and other timing functions. #if defined(LAMARC_QA_DYNAMETER) || defined(LAMARC_QA_TIMINGTEST) unsigned long long int rdtsc() { unsigned int a, d; __asm__ volatile("rdtsc" : "=a" (a), "=d" (d)); return (static_cast(a)) | ((static_cast(d)) << 32); } #endif // defined(LAMARC_QA_DYNAMETER) || defined(LAMARC_QA_TIMINGTEST) //____________________________________________________________________________________