core(logger): dump timestamp information with message

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

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; \

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 =

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);