[feat] Add a lightweight time profiler in the framework

[vkarak]

This PR adds a lightweight time profiler for the framework. This is intended to be a standalone package, that's why the ProfilerError does not extend the ReframeError. The profiler is hierarchical and maintains a stack of regions. The current region is the one at the top of the stack. Every call to enter_region() pushes a new named region in the stack and every exit_region() pops the last region. For convenience a context manager (time_region) is provided for timing a code region.

The framework uses a global profiler defined in core/logging.py and is accessible through the getprofiler() call. For convenience we also define two function decorators for profiling any function in the framework using the global profiler. The profiling info is printed in debug output at the end of the framework's execution.

An example output of the profiler is the following:

>>> profiler report [start] <<<
main: 354.318077 s
    test processing: 353.787054 s
        RegressionCheckLoader.load_all: 0.125004 s
            TestRegistry.instantiate_all: 0.048652 s
        generate_testcases: 0.002782 s
        build_deps: 0.003423 s
        validate_deps: 0.002487 s
        toposort: 0.003798 s
        Runner.runall: 353.594993 s
            RegressionTask.setup: 2.885694 s
            RegressionTask.compile: 69.665549 s
            RegressionTask.compile_complete: 1.234667 s
            RegressionTask.compile_wait: 1.174653 s
            RegressionTask.run: 233.338925 s
            RegressionTask.run_complete: 4.288248 s
            RegressionTask.run_wait: 1.156383 s
            RegressionTask.sanity: 1.874554 s
            RegressionTask.performance: 2.172124 s
            RegressionTask.finalize: 1.176118 s
            RegressionTask.cleanup: 4.646360 s
>>> profiler report [ end ] <<<

Finally, I measured the overhead of the profiler and is ~1us per enter/exit_region combination on my Mac (2.3GHz quad-core Intel Core i5).

This PR builds on top of #2544.

Properly fixes #97.

[victorusu]

Just two crazy questions...

1. Let's imagine that a user would like to also measure their own test hooks...
   The timings would be per test, not per test case, right? If that's the case, how could someone add a test case-specific timing?
2. The intention is to measure the framework, right? That's the reason why the _profiler is defined in the core/logging.py file... However, would it make sense to have a timing function on the utilities? Especially to help with question 1?

[victorusu]

BTW... lgtm

[vkarak]

Let's imagine that a user would like to also measure their own test hooks...
The timings would be per test, not per test case, right? If that's the case, how could someone add a test case-specific timing?

The timings depend on the user. If you use the @time_function decorator, then yes, it will per class instance and it will show the cumulative hook time for all object instantiated from this class, i.e., for every test case. If you want to have separate timing per case, you should use the time_region context manager and name the region either after the unique or the display name of the test.

The intention is to measure the framework, right? That's the reason why the _profiler is defined in the core/logging.py file... However, would it make sense to have a timing function on the utilities? Especially to help with question 1?

Yes, the intention is to measure the framework performance and not to make available –at least for now– the profiler to the users. Let's concrete cases where this could be useful and we can "open it up."

[vkarak]

@jenkins-cscs retry daint