trace: initial support for code trace

modules/ts/include/opencv2/ts.hpp

@@ -1,7 +1,22 @@
 #ifndef OPENCV_TS_HPP
 #define OPENCV_TS_HPP
 
-#include "opencv2/core/cvdef.h"
+#ifndef __OPENCV_TESTS
+#define __OPENCV_TESTS 1
+#endif
+
+#include "opencv2/opencv_modules.hpp"
+
+#include "opencv2/core.hpp"
+#include "opencv2/imgproc.hpp"
+#include "opencv2/imgcodecs.hpp"
+#include "opencv2/videoio.hpp"
+#include "opencv2/highgui.hpp"
+
+#include "opencv2/core/utility.hpp"
+
+#include "opencv2/core/utils/trace.hpp"
+
 #include <stdarg.h> // for va_list
 
 #include "cvconfig.h"
@@ -46,9 +61,6 @@
 #define PARAM_TEST_CASE(name, ...) struct name : testing::TestWithParam< std::tr1::tuple< __VA_ARGS__ > >
 #define GET_PARAM(k) std::tr1::get< k >(GetParam())
 
-#include "opencv2/core.hpp"
-#include "opencv2/core/utility.hpp"
-
 namespace cvtest
 {
 
@@ -615,6 +627,8 @@ void parseCustomOptions(int argc, char **argv);
 #define CV_TEST_MAIN_EX(resourcesubdir, INIT0, ...) \
 int main(int argc, char **argv) \
 { \
+    CV_TRACE_FUNCTION(); \
+    { CV_TRACE_REGION("INIT"); \
     using namespace cvtest; \
     TS* ts = TS::ptr(); \
     ts->init(resourcesubdir); \
@@ -624,6 +638,7 @@ int main(int argc, char **argv) \
     TEST_DUMP_OCL_INFO \
     __CV_TEST_EXEC_ARGS(__VA_ARGS__) \
     parseCustomOptions(argc, argv); \
+    } \
     return RUN_ALL_TESTS(); \
 }
 

modules/ts/include/opencv2/ts/cuda_perf.hpp

@@ -43,12 +43,9 @@
 #ifndef OPENCV_CUDA_PERF_UTILITY_HPP
 #define OPENCV_CUDA_PERF_UTILITY_HPP
 
-#include "opencv2/core.hpp"
-#include "opencv2/imgcodecs.hpp"
-#include "opencv2/videoio.hpp"
-#include "opencv2/imgproc.hpp"
+#include "opencv2/ts.hpp"
+
 #include "opencv2/ts/ts_perf.hpp"
-#include "cvconfig.h"
 
 namespace perf
 {

modules/ts/include/opencv2/ts/cuda_test.hpp

@@ -43,15 +43,11 @@
 #ifndef OPENCV_CUDA_TEST_UTILITY_HPP
 #define OPENCV_CUDA_TEST_UTILITY_HPP
 
-#include <stdexcept>
-#include "cvconfig.h"
-#include "opencv2/core.hpp"
-#include "opencv2/core/cuda.hpp"
-#include "opencv2/imgcodecs.hpp"
-#include "opencv2/highgui.hpp"
-#include "opencv2/imgproc.hpp"
 #include "opencv2/ts.hpp"
 
+#include <stdexcept>
+#include "opencv2/core/cuda.hpp"
+
 namespace cvtest
 {
     //////////////////////////////////////////////////////////////////////

modules/ts/include/opencv2/ts/ocl_perf.hpp

@@ -42,6 +42,8 @@
 #ifndef OPENCV_TS_OCL_PERF_HPP
 #define OPENCV_TS_OCL_PERF_HPP
 
+#include "opencv2/ts.hpp"
+
 #include "ocl_test.hpp"
 #include "ts_perf.hpp"
 
@@ -67,7 +69,7 @@ using std::tr1::tuple;
     protected: \
         virtual void PerfTestBody(); \
     }; \
-    TEST_F(OCL##_##fixture##_##name, name) { declare.strategy(OCL_PERF_STRATEGY); RunPerfTestBody(); } \
+    TEST_F(OCL##_##fixture##_##name, name) { CV_TRACE_REGION("PERF_TEST: " #fixture "_" #name); declare.strategy(OCL_PERF_STRATEGY); RunPerfTestBody(); } \
     void OCL##_##fixture##_##name::PerfTestBody()
 
 #define SIMPLE_PERF_TEST_P(fixture, name, params) \
@@ -79,7 +81,7 @@ using std::tr1::tuple;
     protected: \
         virtual void PerfTestBody(); \
     }; \
-    TEST_P(OCL##_##fixture##_##name, name) { declare.strategy(OCL_PERF_STRATEGY); RunPerfTestBody(); } \
+    TEST_P(OCL##_##fixture##_##name, name) { CV_TRACE_REGION("PERF_TEST_P: " #fixture "_" #name); declare.strategy(OCL_PERF_STRATEGY); RunPerfTestBody(); } \
     INSTANTIATE_TEST_CASE_P(/*none*/, OCL##_##fixture##_##name, params); \
     void OCL##_##fixture##_##name::PerfTestBody()
 
@@ -95,17 +97,27 @@ using std::tr1::tuple;
 
 #define OCL_PERF_ENUM ::testing::Values
 
-// TODO Replace finish call to dstUMat.wait()
+//! deprecated
 #define OCL_TEST_CYCLE() \
     for (cvtest::ocl::perf::safeFinish(); next() && startTimer(); cvtest::ocl::perf::safeFinish(), stopTimer())
-
+//! deprecated
 #define OCL_TEST_CYCLE_N(n) \
     for (declare.iterations(n), cvtest::ocl::perf::safeFinish(); next() && startTimer(); cvtest::ocl::perf::safeFinish(), stopTimer())
-
+//! deprecated
 #define OCL_TEST_CYCLE_MULTIRUN(runsNum) \
     for (declare.runs(runsNum), cvtest::ocl::perf::safeFinish(); next() && startTimer(); cvtest::ocl::perf::safeFinish(), stopTimer()) \
         for (int r = 0; r < runsNum; cvtest::ocl::perf::safeFinish(), ++r)
 
+#undef PERF_SAMPLE_BEGIN
+#undef PERF_SAMPLE_END
+#define PERF_SAMPLE_BEGIN() \
+    cvtest::ocl::perf::safeFinish(); \
+    for(; next() && startTimer(); cvtest::ocl::perf::safeFinish(), stopTimer()) \
+    { \
+        CV_TRACE_REGION("iteration");
+#define PERF_SAMPLE_END() \
+    }
+
 
 namespace perf {
 

modules/ts/include/opencv2/ts/ocl_test.hpp

@@ -42,8 +42,6 @@
 #ifndef OPENCV_TS_OCL_TEST_HPP
 #define OPENCV_TS_OCL_TEST_HPP
 
-#include "opencv2/opencv_modules.hpp"
-
 #include "opencv2/ts.hpp"
 
 #include "opencv2/imgcodecs.hpp"

modules/ts/include/opencv2/ts/ts_ext.hpp

@@ -16,8 +16,9 @@ void checkIppStatus();
     cv::ipp::setIppStatus(0); \
     cv::theRNG().state = cvtest::param_seed;
 #define CV_TEST_CLEANUP ::cvtest::checkIppStatus();
-#define CV_TEST_BODY_IMPL \
+#define CV_TEST_BODY_IMPL(name) \
     { \
+       CV__TRACE_APP_FUNCTION_NAME(name); \
        try { \
           CV_TEST_INIT \
           Body(); \
@@ -53,7 +54,7 @@ void checkIppStatus();
             ::testing::Test::TearDownTestCase, \
             new ::testing::internal::TestFactoryImpl<\
                 GTEST_TEST_CLASS_NAME_(test_case_name, test_name)>);\
-    void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::TestBody() CV_TEST_BODY_IMPL \
+    void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::TestBody() CV_TEST_BODY_IMPL( #test_case_name "_" #test_name ) \
     void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::Body()
 
 #undef TEST_F
@@ -79,7 +80,7 @@ void checkIppStatus();
             test_fixture::TearDownTestCase, \
             new ::testing::internal::TestFactoryImpl<\
                 GTEST_TEST_CLASS_NAME_(test_fixture, test_name)>);\
-    void GTEST_TEST_CLASS_NAME_(test_fixture, test_name)::TestBody() CV_TEST_BODY_IMPL \
+    void GTEST_TEST_CLASS_NAME_(test_fixture, test_name)::TestBody() CV_TEST_BODY_IMPL( #test_fixture "_" #test_name ) \
     void GTEST_TEST_CLASS_NAME_(test_fixture, test_name)::Body()
 
 #undef TEST_P
@@ -111,7 +112,7 @@ void checkIppStatus();
   int GTEST_TEST_CLASS_NAME_(test_case_name, \
                              test_name)::gtest_registering_dummy_ = \
       GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::AddToRegistry(); \
-    void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::TestBody() CV_TEST_BODY_IMPL \
+    void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::TestBody() CV_TEST_BODY_IMPL( #test_case_name "_" #test_name ) \
     void GTEST_TEST_CLASS_NAME_(test_case_name, test_name)::Body()
 
 #endif  // OPENCV_TS_EXT_HPP

modules/ts/include/opencv2/ts/ts_perf.hpp

@@ -1,7 +1,8 @@
 #ifndef OPENCV_TS_PERF_HPP
 #define OPENCV_TS_PERF_HPP
 
-#include "opencv2/core.hpp"
+#include "opencv2/ts.hpp"
+
 #include "ts_gtest.h"
 #include "ts_ext.hpp"
 
@@ -537,7 +538,7 @@ CV_EXPORTS void PrintTo(const Size& sz, ::std::ostream* os);
       protected:\
        virtual void PerfTestBody();\
      };\
-     TEST_F(test_case_name, test_name){ RunPerfTestBody(); }\
+     TEST_F(test_case_name, test_name){ CV_TRACE_REGION("PERF_TEST: " #test_case_name "_" #test_name); RunPerfTestBody(); }\
     }\
     void PERF_PROXY_NAMESPACE_NAME_(test_case_name, test_name)::test_case_name::PerfTestBody()
 
@@ -575,7 +576,7 @@ CV_EXPORTS void PrintTo(const Size& sz, ::std::ostream* os);
       protected:\
        virtual void PerfTestBody();\
      };\
-     TEST_F(fixture, testname){ RunPerfTestBody(); }\
+     TEST_F(fixture, testname){ CV_TRACE_REGION("PERF_TEST: " #fixture "_" #testname); RunPerfTestBody(); }\
     }\
     void PERF_PROXY_NAMESPACE_NAME_(fixture, testname)::fixture::PerfTestBody()
 
@@ -608,7 +609,7 @@ CV_EXPORTS void PrintTo(const Size& sz, ::std::ostream* os);
      protected:\
       virtual void PerfTestBody();\
     };\
-    TEST_P(fixture##_##name, name /*perf*/){ RunPerfTestBody(); }\
+    TEST_P(fixture##_##name, name /*perf*/){ CV_TRACE_REGION("PERF_TEST: " #fixture "_" #name); RunPerfTestBody(); }\
     INSTANTIATE_TEST_CASE_P(/*none*/, fixture##_##name, params);\
     void fixture##_##name::PerfTestBody()
 
@@ -631,7 +632,10 @@ void dumpOpenCLDevice();
 #define TEST_DUMP_OCL_INFO
 #endif
 
+
 #define CV_PERF_TEST_MAIN_INTERNALS(modulename, impls, ...)	\
+    CV_TRACE_FUNCTION(); \
+    { CV_TRACE_REGION("INIT"); \
     ::perf::Regression::Init(#modulename); \
     ::perf::TestBase::Init(std::vector<std::string>(impls, impls + sizeof impls / sizeof *impls), \
                            argc, argv); \
@@ -641,6 +645,7 @@ void dumpOpenCLDevice();
     ::perf::TestBase::RecordRunParameters(); \
     __CV_TEST_EXEC_ARGS(__VA_ARGS__) \
     TEST_DUMP_OCL_INFO \
+    } \
     return RUN_ALL_TESTS();
 
 // impls must be an array, not a pointer; "plain" should always be one of the implementations
@@ -657,10 +662,20 @@ int main(int argc, char **argv)\
     CV_PERF_TEST_MAIN_INTERNALS(modulename, plain_only, __VA_ARGS__)\
 }
 
+//! deprecated
 #define TEST_CYCLE_N(n) for(declare.iterations(n); next() && startTimer(); stopTimer())
+//! deprecated
 #define TEST_CYCLE() for(; next() && startTimer(); stopTimer())
+//! deprecated
 #define TEST_CYCLE_MULTIRUN(runsNum) for(declare.runs(runsNum); next() && startTimer(); stopTimer()) for(int r = 0; r < runsNum; ++r)
 
+#define PERF_SAMPLE_BEGIN() \
+    for(; next() && startTimer(); stopTimer()) \
+    { \
+        CV_TRACE_REGION("iteration");
+#define PERF_SAMPLE_END() \
+    }
+
 namespace perf
 {
 namespace comparators

modules/ts/misc/run.py

@@ -49,6 +49,9 @@ if __name__ == "__main__":
     parser.add_argument("--serial", metavar="serial number", default="", help="Android: directs command to the USB device or emulator with the given serial number")
     parser.add_argument("--package", metavar="package", default="", help="Android: run jUnit tests for specified package")
 
+    parser.add_argument("--trace", action="store_true", default=False, help="Trace: enable OpenCV tracing")
+    parser.add_argument("--trace_dump", metavar="trace_dump", default=-1, help="Trace: dump highlight calls (specify max entries count, 0 - dump all)")
+
     args, other_args = parser.parse_known_args()
 
     log.setLevel(logging.DEBUG if args.verbose else logging.INFO)

modules/ts/misc/run_suite.py

@@ -4,6 +4,8 @@ import datetime
 from run_utils import *
 from run_long import LONG_TESTS_DEBUG_VALGRIND, longTestFilter
 
+timestamp = datetime.datetime.now()
+
 class TestSuite(object):
     def __init__(self, options, cache):
         self.options = options
@@ -20,7 +22,8 @@ class TestSuite(object):
             res.append("CUDA")
         return res
 
-    def getLogName(self, app, timestamp):
+    def getLogBaseName(self, app):
+        global timestamp
         app = self.getAlias(app)
         rev = self.cache.getGitVersion()
         if isinstance(timestamp, datetime.datetime):
@@ -34,7 +37,10 @@ class TestSuite(object):
             lname = "_".join([p for p in pieces if p])
             lname = re.sub(r'[\(\)\[\]\s,]', '_', lname)
             l = re.sub(r'_+', '_', lname)
-        return l + ".xml"
+        return l
+
+    def getLogName(self, app):
+        return self.getLogBaseName(app) + '.xml'
 
     def listTests(self, short = False, main = False):
         if len(self.tests) == 0:
@@ -138,10 +144,25 @@ class TestSuite(object):
             if isColorEnabled(args):
                 args.append("--gtest_color=yes")
             cmd = self.wrapInValgrind([exe] + args)
+            env = {}
+            if not self.options.valgrind and self.options.trace:
+                env['OPENCV_TRACE'] = '1'
+                env['OPENCV_TRACE_LOCATION'] = 'OpenCVTrace-{}'.format(self.getLogBaseName(exe))
+                env['OPENCV_TRACE_SYNC_OPENCL'] = '1'
             tempDir = TempEnvDir('OPENCV_TEMP_PATH', "__opencv_temp.")
             tempDir.init()
             log.warning("Run: %s" % " ".join(cmd))
-            ret = execute(cmd, cwd = workingDir)
+            ret = execute(cmd, cwd = workingDir, env=env)
+            try:
+                if not self.options.valgrind and self.options.trace and int(self.options.trace_dump) >= 0:
+                    import trace_profiler
+                    trace = trace_profiler.Trace(env['OPENCV_TRACE_LOCATION']+'.txt')
+                    trace.process()
+                    trace.dump(max_entries=int(self.options.trace_dump))
+            except:
+                import traceback
+                traceback.print_exc()
+                pass
             tempDir.clean()
             hostlogpath = os.path.join(workingDir, logfile)
             if os.path.isfile(hostlogpath):
@@ -157,7 +178,6 @@ class TestSuite(object):
         args = args[:]
         logs = []
         test_list = self.getTestList(tests, black)
-        date = datetime.datetime.now()
         if len(test_list) != 1:
             args = [a for a in args if not a.startswith("--gtest_output=")]
         ret = 0
@@ -170,7 +190,7 @@ class TestSuite(object):
             else:
                 userlog = [a for a in args if a.startswith("--gtest_output=")]
                 if len(userlog) == 0:
-                    logname = self.getLogName(exe, date)
+                    logname = self.getLogName(exe)
                     more_args.append("--gtest_output=xml:" + logname)
                 else:
                     logname = userlog[0][userlog[0].find(":")+1:]

modules/ts/misc/run_utils.py

@@ -25,10 +25,12 @@ class Err(Exception):
 def execute(cmd, silent = False, cwd = ".", env = None):
     try:
         log.debug("Run: %s", cmd)
-        if env:
+        if env is not None:
             for k in env:
                 log.debug("    Environ: %s=%s", k, env[k])
-            env = os.environ.update(env)
+            new_env = os.environ.copy()
+            new_env.update(env)
+            env = new_env
         if silent:
             return check_output(cmd, stderr = STDOUT, cwd = cwd, env = env).decode("latin-1")
         else:

modules/ts/misc/trace_profiler.py

@@ -0,0 +1,435 @@
+from __future__ import print_function
+
+import os
+import sys
+import csv
+from pprint import pprint
+from collections import deque
+
+# trace.hpp
+REGION_FLAG_IMPL_MASK = 15 << 16;
+REGION_FLAG_IMPL_IPP = 1 << 16;
+REGION_FLAG_IMPL_OPENCL = 2 << 16;
+
+DEBUG = False
+
+if DEBUG:
+    dprint = print
+    dpprint = pprint
+else:
+    def dprint(args, **kwargs):
+        pass
+    def dpprint(args, **kwargs):
+        pass
+
+def tryNum(s):
+    if s.startswith('0x'):
+        try:
+            return int(s, 16)
+        except ValueError:
+            pass
+    try:
+        return int(s)
+    except ValueError:
+        pass
+    if sys.version_info[0] < 3:
+        try:
+            return long(s)
+        except ValueError:
+            pass
+    return s
+
+def formatTimestamp(t):
+    return "%.3f" % (t * 1e-6)
+
+try:
+    from statistics import median
+except ImportError:
+    def median(lst):
+        sortedLst = sorted(lst)
+        lstLen = len(lst)
+        index = (lstLen - 1) // 2
+        if (lstLen % 2):
+            return sortedLst[index]
+        else:
+            return (sortedLst[index] + sortedLst[index + 1]) * 0.5
+
+def getCXXFunctionName(spec):
+    def dropParams(spec):
+        pos = len(spec) - 1
+        depth = 0
+        while pos >= 0:
+            if spec[pos] == ')':
+                depth = depth + 1
+            elif spec[pos] == '(':
+                depth = depth - 1
+                if depth == 0:
+                    if pos == 0 or spec[pos - 1] in ['#', ':']:
+                        res = dropParams(spec[pos+1:-1])
+                        return (spec[:pos] + res[0], res[1])
+                    return (spec[:pos], spec[pos:])
+            pos = pos - 1
+        return (spec, '')
+
+    def extractName(spec):
+        pos = len(spec) - 1
+        inName = False
+        while pos >= 0:
+            if spec[pos] == ' ':
+                if inName:
+                    return spec[pos+1:]
+            elif spec[pos].isalnum():
+                inName = True
+            pos = pos - 1
+        return spec
+
+    if spec.startswith('IPP') or spec.startswith('OpenCL'):
+        prefix_size = len('IPP') if spec.startswith('IPP') else len('OpenCL')
+        prefix = spec[:prefix_size]
+        if prefix_size < len(spec) and spec[prefix_size] in ['#', ':']:
+            prefix = prefix + spec[prefix_size]
+            prefix_size = prefix_size + 1
+        begin = prefix_size
+        while begin < len(spec):
+            if spec[begin].isalnum() or spec[begin] in ['_', ':']:
+                break
+            begin = begin + 1
+        if begin == len(spec):
+            return spec
+        end = begin
+        while end < len(spec):
+            if not (spec[end].isalnum() or spec[end] in ['_', ':']):
+                break
+            end = end + 1
+        return prefix + spec[begin:end]
+
+    spec = spec.replace(') const', ')') # const methods
+    (ret_type_name, params) = dropParams(spec)
+    name = extractName(ret_type_name)
+    if 'operator' in name:
+        return name + params
+    if name.startswith('&'):
+        return name[1:]
+    return name
+
+stack_size = 10
+
+class Trace:
+    def __init__(self, filename=None):
+        self.tasks = {}
+        self.tasks_list = []
+        self.locations = {}
+        self.threads_stack = {}
+        self.pending_files = deque()
+        if filename:
+            self.load(filename)
+
+    class TraceTask:
+        def __init__(self, threadID, taskID, locationID, beginTimestamp):
+            self.threadID = threadID
+            self.taskID = taskID
+            self.locationID = locationID
+            self.beginTimestamp = beginTimestamp
+            self.endTimestamp = None
+            self.parentTaskID = None
+            self.parentThreadID = None
+            self.childTask = []
+            self.selfTimeIPP = 0
+            self.selfTimeOpenCL = 0
+            self.totalTimeIPP = 0
+            self.totalTimeOpenCL = 0
+
+        def __repr__(self):
+            return "TID={} ID={} loc={} parent={}:{} begin={} end={} IPP={}/{} OpenCL={}/{}".format(
+                self.threadID, self.taskID, self.locationID, self.parentThreadID, self.parentTaskID,
+                self.beginTimestamp, self.endTimestamp, self.totalTimeIPP, self.selfTimeIPP, self.totalTimeOpenCL, self.selfTimeOpenCL)
+
+
+    class TraceLocation:
+        def __init__(self, locationID, filename, line, name, flags):
+            self.locationID = locationID
+            self.filename = os.path.split(filename)[1]
+            self.line = line
+            self.name = getCXXFunctionName(name)
+            self.flags = flags
+
+        def __str__(self):
+            return "{}#{}:{}".format(self.name, self.filename, self.line)
+
+        def __repr__(self):
+            return "ID={} {}:{}:{}".format(self.locationID, self.filename, self.line, self.name)
+
+    def parse_file(self, filename):
+        dprint("Process file: '{}'".format(filename))
+        with open(filename) as infile:
+            for line in infile:
+                line = str(line).strip()
+                if line[0] == "#":
+                    if line.startswith("#thread file:"):
+                        name = str(line.split(':', 1)[1]).strip()
+                        self.pending_files.append(os.path.join(os.path.split(filename)[0], name))
+                    continue
+                self.parse_line(line)
+
+    def parse_line(self, line):
+        opts = line.split(',')
+        dpprint(opts)
+        if opts[0] == 'l':
+            opts = list(csv.reader([line]))[0]  # process quote more
+            locationID = int(opts[1])
+            filename = str(opts[2])
+            line = int(opts[3])
+            name = opts[4]
+            flags = tryNum(opts[5])
+            self.locations[locationID] = self.TraceLocation(locationID, filename, line, name, flags)
+            return
+        extra_opts = {}
+        for e in opts[5:]:
+            if not '=' in e:
+                continue
+            (k, v) = e.split('=')
+            extra_opts[k] = tryNum(v)
+        if extra_opts:
+            dpprint(extra_opts)
+        threadID = None
+        taskID = None
+        locationID = None
+        ts = None
+        if opts[0] in ['b', 'e']:
+            threadID = int(opts[1])
+            taskID = int(opts[4])
+            locationID = int(opts[3])
+            ts = tryNum(opts[2])
+        thread_stack = None
+        currentTask = (None, None)
+        if threadID is not None:
+            if not threadID in self.threads_stack:
+                thread_stack = deque()
+                self.threads_stack[threadID] = thread_stack
+            else:
+                thread_stack = self.threads_stack[threadID]
+            currentTask = None if not thread_stack else thread_stack[-1]
+        t = (threadID, taskID)
+        if opts[0] == 'b':
+            assert not t in self.tasks, "Duplicate task: " + str(t) + repr(self.tasks[t])
+            task = self.TraceTask(threadID, taskID, locationID, ts)
+            self.tasks[t] = task
+            self.tasks_list.append(task)
+            thread_stack.append((threadID, taskID))
+            if currentTask:
+                task.parentThreadID = currentTask[0]
+                task.parentTaskID = currentTask[1]
+            if 'parentThread' in extra_opts:
+                task.parentThreadID = extra_opts['parentThread']
+            if 'parent' in extra_opts:
+                task.parentTaskID = extra_opts['parent']
+        if opts[0] == 'e':
+            task = self.tasks[t]
+            task.endTimestamp = ts
+            if 'tIPP' in extra_opts:
+                task.selfTimeIPP = extra_opts['tIPP']
+            if 'tOCL' in extra_opts:
+                task.selfTimeOpenCL = extra_opts['tOCL']
+            thread_stack.pop()
+
+    def load(self, filename):
+        self.pending_files.append(filename)
+        if DEBUG:
+            with open(filename, 'r') as f:
+                print(f.read(), end='')
+        while self.pending_files:
+            self.parse_file(self.pending_files.pop())
+
+    def getParentTask(self, task):
+        return self.tasks.get((task.parentThreadID, task.parentTaskID), None)
+
+    def process(self):
+        self.tasks_list.sort(key=lambda x: x.beginTimestamp)
+
+        parallel_for_location = None
+        for (id, l) in self.locations.items():
+            if l.name == 'parallel_for':
+                parallel_for_location = l.locationID
+                break
+
+        for task in self.tasks_list:
+            try:
+                task.duration = task.endTimestamp - task.beginTimestamp
+                task.selfDuration = task.duration
+            except:
+                task.duration = None
+                task.selfDuration = None
+            task.totalTimeIPP = task.selfTimeIPP
+            task.totalTimeOpenCL = task.selfTimeOpenCL
+
+        dpprint(self.tasks)
+        dprint("Calculate total times")
+
+        for task in self.tasks_list:
+            parentTask = self.getParentTask(task)
+            if parentTask:
+                parentTask.selfDuration = parentTask.selfDuration - task.duration
+                parentTask.childTask.append(task)
+                timeIPP = task.selfTimeIPP
+                timeOpenCL = task.selfTimeOpenCL
+                while parentTask:
+                    if parentTask.locationID == parallel_for_location:  # TODO parallel_for
+                        break
+                    parentLocation = self.locations[parentTask.locationID]
+                    if (parentLocation.flags & REGION_FLAG_IMPL_MASK) == REGION_FLAG_IMPL_IPP:
+                        parentTask.selfTimeIPP = parentTask.selfTimeIPP - timeIPP
+                        timeIPP = 0
+                    else:
+                        parentTask.totalTimeIPP = parentTask.totalTimeIPP + timeIPP
+                    if (parentLocation.flags & REGION_FLAG_IMPL_MASK) == REGION_FLAG_IMPL_OPENCL:
+                        parentTask.selfTimeOpenCL = parentTask.selfTimeOpenCL - timeOpenCL
+                        timeOpenCL = 0
+                    else:
+                        parentTask.totalTimeOpenCL = parentTask.totalTimeOpenCL + timeOpenCL
+                    parentTask = self.getParentTask(parentTask)
+
+        dpprint(self.tasks)
+        dprint("Calculate total times (parallel_for)")
+
+        for task in self.tasks_list:
+            if task.locationID == parallel_for_location:
+                task.selfDuration = 0
+                childDuration = sum([t.duration for t in task.childTask])
+                if task.duration == 0 or childDuration == 0:
+                    continue
+                timeCoef = task.duration / float(childDuration)
+                childTimeIPP = sum([t.totalTimeIPP for t in task.childTask])
+                childTimeOpenCL = sum([t.totalTimeOpenCL for t in task.childTask])
+                if childTimeIPP == 0 and childTimeOpenCL == 0:
+                    continue
+                timeIPP = childTimeIPP * timeCoef
+                timeOpenCL = childTimeOpenCL * timeCoef
+                parentTask = task
+                while parentTask:
+                    parentLocation = self.locations[parentTask.locationID]
+                    if (parentLocation.flags & REGION_FLAG_IMPL_MASK) == REGION_FLAG_IMPL_IPP:
+                        parentTask.selfTimeIPP = parentTask.selfTimeIPP - timeIPP
+                        timeIPP = 0
+                    else:
+                        parentTask.totalTimeIPP = parentTask.totalTimeIPP + timeIPP
+                    if (parentLocation.flags & REGION_FLAG_IMPL_MASK) == REGION_FLAG_IMPL_OPENCL:
+                        parentTask.selfTimeOpenCL = parentTask.selfTimeOpenCL - timeOpenCL
+                        timeOpenCL = 0
+                    else:
+                        parentTask.totalTimeOpenCL = parentTask.totalTimeOpenCL + timeOpenCL
+                    parentTask = self.getParentTask(parentTask)
+
+        dpprint(self.tasks)
+        dprint("Done")
+
+    def dump(self, max_entries):
+        assert isinstance(max_entries, int)
+
+        class CallInfo():
+            def __init__(self, callID):
+                self.callID = callID
+                self.totalTimes = []
+                self.selfTimes = []
+                self.threads = set()
+                self.selfTimesIPP = []
+                self.selfTimesOpenCL = []
+                self.totalTimesIPP = []
+                self.totalTimesOpenCL = []
+
+        calls = {}
+
+        for currentTask in self.tasks_list:
+            task = currentTask
+            callID = []
+            for i in range(stack_size):
+                callID.append(task.locationID)
+                task = self.getParentTask(task)
+                if not task:
+                    break
+            callID = tuple(callID)
+            if not callID in calls:
+                call = CallInfo(callID)
+                calls[callID] = call
+            else:
+                call = calls[callID]
+            call.totalTimes.append(currentTask.duration)
+            call.selfTimes.append(currentTask.selfDuration)
+            call.threads.add(currentTask.threadID)
+            call.selfTimesIPP.append(currentTask.selfTimeIPP)
+            call.selfTimesOpenCL.append(currentTask.selfTimeOpenCL)
+            call.totalTimesIPP.append(currentTask.totalTimeIPP)
+            call.totalTimesOpenCL.append(currentTask.totalTimeOpenCL)
+
+        dpprint(self.tasks)
+        dpprint(self.locations)
+        dpprint(calls)
+
+        calls_self_sum = {k: sum(v.selfTimes) for (k, v) in calls.items()}
+        calls_total_sum = {k: sum(v.totalTimes) for (k, v) in calls.items()}
+        calls_median = {k: median(v.selfTimes) for (k, v) in calls.items()}
+        calls_sorted = sorted(calls.keys(), key=lambda x: calls_self_sum[x], reverse=True)
+
+        calls_self_sum_IPP = {k: sum(v.selfTimesIPP) for (k, v) in calls.items()}
+        calls_total_sum_IPP = {k: sum(v.totalTimesIPP) for (k, v) in calls.items()}
+
+        calls_self_sum_OpenCL = {k: sum(v.selfTimesOpenCL) for (k, v) in calls.items()}
+        calls_total_sum_OpenCL = {k: sum(v.totalTimesOpenCL) for (k, v) in calls.items()}
+
+        if max_entries > 0 and len(calls_sorted) > max_entries:
+            calls_sorted = calls_sorted[:max_entries]
+
+        def formatPercents(p):
+            if p is not None:
+                return "{:>3d}".format(int(p*100))
+            return ''
+
+        name_width = 70
+        timestamp_width = 12
+        def fmtTS():
+            return '{:>' + str(timestamp_width) + '}'
+        fmt = "{:>3} {:<"+str(name_width)+"} {:>8} {:>3}"+((' '+fmtTS())*5)+((' '+fmtTS()+' {:>3}')*2)
+        fmt2 = "{:>3} {:<"+str(name_width)+"} {:>8} {:>3}"+((' '+fmtTS())*5)+((' '+fmtTS()+' {:>3}')*2)
+        print(fmt.format("ID", "name", "count", "thr", "min", "max", "median", "avg", "*self*", "IPP", "%", "OpenCL", "%"))
+        print(fmt2.format("", "", "", "", "t-min", "t-max", "t-median", "t-avg", "total", "t-IPP", "%", "t-OpenCL", "%"))
+        for (index, callID) in enumerate(calls_sorted):
+            call_self_times = calls[callID].selfTimes
+            loc0 = self.locations[callID[0]]
+            loc_array = []  # [str(callID)]
+            for (i, l) in enumerate(callID):
+                loc = self.locations[l]
+                loc_array.append(loc.name if i > 0 else str(loc))
+            loc_str = '|'.join(loc_array)
+            if len(loc_str) > name_width: loc_str = loc_str[:name_width-3]+'...'
+            print(fmt.format(index + 1, loc_str, len(call_self_times),
+                    len(calls[callID].threads),
+                    formatTimestamp(min(call_self_times)),
+                    formatTimestamp(max(call_self_times)),
+                    formatTimestamp(calls_median[callID]),
+                    formatTimestamp(sum(call_self_times)/float(len(call_self_times))),
+                    formatTimestamp(sum(call_self_times)),
+                    formatTimestamp(calls_self_sum_IPP[callID]),
+                    formatPercents(calls_self_sum_IPP[callID] / float(calls_self_sum[callID])) if calls_self_sum[callID] > 0 else formatPercents(None),
+                    formatTimestamp(calls_self_sum_OpenCL[callID]),
+                    formatPercents(calls_self_sum_OpenCL[callID] / float(calls_self_sum[callID])) if calls_self_sum[callID] > 0 else formatPercents(None),
+                ))
+            call_total_times = calls[callID].totalTimes
+            print(fmt2.format("", "", "", "",
+                    formatTimestamp(min(call_total_times)),
+                    formatTimestamp(max(call_total_times)),
+                    formatTimestamp(median(call_total_times)),
+                    formatTimestamp(sum(call_total_times)/float(len(call_total_times))),
+                    formatTimestamp(sum(call_total_times)),
+                    formatTimestamp(calls_total_sum_IPP[callID]),
+                    formatPercents(calls_total_sum_IPP[callID] / float(calls_total_sum[callID])) if calls_total_sum[callID] > 0 else formatPercents(None),
+                    formatTimestamp(calls_total_sum_OpenCL[callID]),
+                    formatPercents(calls_total_sum_OpenCL[callID] / float(calls_total_sum[callID])) if calls_total_sum[callID] > 0 else formatPercents(None),
+                ))
+            print()
+
+if __name__ == "__main__":
+    tracefile = sys.argv[1] if len(sys.argv) > 1 else 'OpenCVTrace.txt'
+    count = int(sys.argv[2]) if len(sys.argv) > 2 else 10
+    trace = Trace(tracefile)
+    trace.process()
+    trace.dump(max_entries = count)
+    print("OK")

modules/ts/src/precomp.hpp

@@ -1,7 +1,5 @@
-#include "opencv2/core/utility.hpp"
-#include "opencv2/core/private.hpp"
 #include "opencv2/ts.hpp"
-#include "cvconfig.h"
+#include "opencv2/core/private.hpp"
 
 #ifdef GTEST_LINKED_AS_SHARED_LIBRARY
 #error ts module should not have GTEST_LINKED_AS_SHARED_LIBRARY defined

modules/ts/src/ts.cpp

@@ -225,6 +225,7 @@ bool BaseTest::can_do_fast_forward()
 
 void BaseTest::safe_run( int start_from )
 {
+    CV_TRACE_FUNCTION();
     read_params( ts->get_file_storage() );
     ts->update_context( 0, -1, true );
     ts->update_context( this, -1, true );

modules/ts/src/ts_perf.cpp

@@ -954,6 +954,8 @@ void TestBase::Init(int argc, const char* const argv[])
 void TestBase::Init(const std::vector<std::string> & availableImpls,
                  int argc, const char* const argv[])
 {
+    CV_TRACE_FUNCTION();
+
     available_impls = availableImpls;
 
     const std::string command_line_keys =
@@ -1182,6 +1184,7 @@ enum PERF_STRATEGY TestBase::getCurrentModulePerformanceStrategy()
 
 int64 TestBase::_calibrate()
 {
+    CV_TRACE_FUNCTION();
     class _helper : public ::perf::TestBase
     {
         public:
@@ -1248,6 +1251,7 @@ void TestBase::declareArray(SizeVector& sizes, cv::InputOutputArray a, WarmUpTyp
 
 void TestBase::warmup(cv::InputOutputArray a, WarmUpType wtype)
 {
+    CV_TRACE_FUNCTION();
     if (a.empty())
         return;
     else if (a.isUMat())
@@ -1419,6 +1423,7 @@ bool TestBase::next()
                             median_ms > perf_validation_time_threshold_ms &&
                             (grow || metrics.stddev > perf_stability_criteria * fabs(metrics.mean)))
                     {
+                        CV_TRACE_REGION("idle_delay");
                         printf("Performance is unstable, it may be a result of overheat problems\n");
                         printf("Idle delay for %d ms... \n", perf_validation_idle_delay_ms);
 #if defined WIN32 || defined _WIN32 || defined WIN64 || defined _WIN64
@@ -1682,8 +1687,17 @@ void TestBase::validateMetrics()
 
 void TestBase::reportMetrics(bool toJUnitXML)
 {
+    CV_TRACE_FUNCTION();
+
     performance_metrics& m = calcMetrics();
 
+    CV_TRACE_ARG_VALUE(samples, "samples", (int64)m.samples);
+    CV_TRACE_ARG_VALUE(outliers, "outliers", (int64)m.outliers);
+    CV_TRACE_ARG_VALUE(median, "mean_ms", (double)(m.mean * 1000.0f / metrics.frequency));
+    CV_TRACE_ARG_VALUE(median, "median_ms", (double)(m.median * 1000.0f / metrics.frequency));
+    CV_TRACE_ARG_VALUE(stddev, "stddev_ms", (double)(m.stddev * 1000.0f / metrics.frequency));
+    CV_TRACE_ARG_VALUE(stddev_percents, "stddev_percents", (double)(m.stddev / (double)m.mean * 100.0f));
+
     if (m.terminationReason == performance_metrics::TERM_SKIP_TEST)
     {
         if (toJUnitXML)