diff --git a/modules/core/src/logger.cpp b/modules/core/src/logger.cpp index c66177c91cc5bd475b33f5fa136c1a6bdda58f9b..94fa3fac5bcec474730a7c1e3162a7c4857c538b 100644 --- a/modules/core/src/logger.cpp +++ b/modules/core/src/logger.cpp @@ -71,17 +71,33 @@ LogLevel getLogLevel() namespace internal { +static int getShowTimestampMode() +{ + static bool param_timestamp_enable = utils::getConfigurationParameterBool("OPENCV_LOG_TIMESTAMP", true); + static bool param_timestamp_ns_enable = utils::getConfigurationParameterBool("OPENCV_LOG_TIMESTAMP_NS", false); + return (param_timestamp_enable ? 1 : 0) + (param_timestamp_ns_enable ? 2 : 0); +} + void writeLogMessage(LogLevel logLevel, const char* message) { const int threadID = cv::utils::getThreadID(); + + std::string message_id; + switch (getShowTimestampMode()) + { + case 1: message_id = cv::format("%d@%0.3f", threadID, getTimestampNS() * 1e-9); break; + case 1+2: message_id = cv::format("%d@%llu", threadID, getTimestampNS()); break; + default: message_id = cv::format("%d", threadID); break; + } + std::ostringstream ss; switch (logLevel) { - case LOG_LEVEL_FATAL: ss << "[FATAL:" << threadID << "] " << message << std::endl; break; - case LOG_LEVEL_ERROR: ss << "[ERROR:" << threadID << "] " << message << std::endl; break; - case LOG_LEVEL_WARNING: ss << "[ WARN:" << threadID << "] " << message << std::endl; break; - case LOG_LEVEL_INFO: ss << "[ INFO:" << threadID << "] " << message << std::endl; break; - case LOG_LEVEL_DEBUG: ss << "[DEBUG:" << threadID << "] " << message << std::endl; break; + case LOG_LEVEL_FATAL: ss << "[FATAL:" << message_id << "] " << message << std::endl; break; + case LOG_LEVEL_ERROR: ss << "[ERROR:" << message_id << "] " << message << std::endl; break; + case LOG_LEVEL_WARNING: ss << "[ WARN:" << message_id << "] " << message << std::endl; break; + case LOG_LEVEL_INFO: ss << "[ INFO:" << message_id << "] " << message << std::endl; break; + case LOG_LEVEL_DEBUG: ss << "[DEBUG:" << message_id << "] " << message << std::endl; break; case LOG_LEVEL_VERBOSE: ss << message << std::endl; break; case LOG_LEVEL_SILENT: return; // avoid compiler warning about incomplete switch case ENUM_LOG_LEVEL_FORCE_INT: return; // avoid compiler warning about incomplete switch diff --git a/modules/core/src/precomp.hpp b/modules/core/src/precomp.hpp index eebbda069447bd1bfb632f5eed73d7ac29029c1b..d30855ef1e9e07cb183631d8b95ff85ccc08d618 100644 --- a/modules/core/src/precomp.hpp +++ b/modules/core/src/precomp.hpp @@ -374,6 +374,10 @@ bool __termination; // skip some cleanups, because process is terminating cv::Mutex& getInitializationMutex(); +/// @brief Returns timestamp in nanoseconds since program launch +int64 getTimestampNS(); + + // TODO Memory barriers? #define CV_SINGLETON_LAZY_INIT_(TYPE, INITIALIZER, RET_VALUE) \ static TYPE* volatile instance = NULL; \ diff --git a/modules/core/src/system.cpp b/modules/core/src/system.cpp index 16e5c749ef642b62490b1256f8fdc6e0e6b885e9..01ed10a7fdd4d629662e2c97b54516ef6ca9348c 100644 --- a/modules/core/src/system.cpp +++ b/modules/core/src/system.cpp @@ -934,6 +934,51 @@ int64 getCPUTickCount(void) #endif + +namespace internal { + +class Timestamp +{ +public: + const int64 zeroTickCount; + const double ns_in_ticks; + + Timestamp() + : zeroTickCount(getTickCount()) + , ns_in_ticks(1e9 / getTickFrequency()) + { + // nothing + } + + int64 getTimestamp() + { + int64 t = getTickCount(); + return (int64)((t - zeroTickCount) * ns_in_ticks); + } + + static Timestamp& getInstance() + { + static Timestamp g_timestamp; + return g_timestamp; + } +}; + +class InitTimestamp { +public: + InitTimestamp() { + Timestamp::getInstance(); + } +}; +static InitTimestamp g_initialize_timestamp; // force zero timestamp initialization + +} // namespace + +int64 getTimestampNS() +{ + return internal::Timestamp::getInstance().getTimestamp(); +} + + const String& getBuildInformation() { static String build_info = diff --git a/modules/core/src/trace.cpp b/modules/core/src/trace.cpp index 1c12c2a2e5e6c0c3fc5a0602b3d91e2d9d07bde2..1011db5e3be2a82b6d8f4a2caf2600a070692503 100644 --- a/modules/core/src/trace.cpp +++ b/modules/core/src/trace.cpp @@ -63,15 +63,6 @@ namespace details { #pragma warning(disable:4065) // switch statement contains 'default' but no 'case' labels #endif -static int64 g_zero_timestamp = 0; - -static int64 getTimestamp() -{ - int64 t = getTickCount(); - static double tick_to_ns = 1e9 / getTickFrequency(); - return (int64)((t - g_zero_timestamp) * tick_to_ns); -} - static bool getParameterTraceEnable() { static bool param_traceEnable = utils::getConfigurationParameterBool("OPENCV_TRACE", false); @@ -485,7 +476,7 @@ Region::Region(const LocationStaticStorage& location) : } } - int64 beginTimestamp = getTimestamp(); + int64 beginTimestamp = getTimestampNS(); int currentDepth = ctx.getCurrentDepth() + 1; switch (location.flags & REGION_FLAG_IMPL_MASK) @@ -635,7 +626,7 @@ void Region::destroy() } } - int64 endTimestamp = getTimestamp(); + int64 endTimestamp = getTimestampNS(); int64 duration = endTimestamp - ctx.stackTopBeginTimestamp(); bool active = isActive(); @@ -844,7 +835,7 @@ static bool isInitialized = false; TraceManager::TraceManager() { - g_zero_timestamp = cv::getTickCount(); + (void)cv::getTimestampNS(); isInitialized = true; CV_LOG("TraceManager ctor: " << (void*)this); @@ -990,7 +981,7 @@ void parallelForFinalize(const Region& rootRegion) { TraceManagerThreadLocal& ctx = getTraceManager().tls.getRef(); - int64 endTimestamp = getTimestamp(); + int64 endTimestamp = getTimestampNS(); int64 duration = endTimestamp - ctx.stackTopBeginTimestamp(); CV_LOG_PARALLEL(NULL, "parallel_for duration: " << duration << " " << &rootRegion);