From 65f96c1429615adf9b522ee0b9fccd04291ce048 Mon Sep 17 00:00:00 2001 From: David Galiffi Date: Mon, 6 Jan 2025 11:27:38 -0500 Subject: [PATCH] Update User-API example (#74) --- docs/how-to/using-rocprof-sys-api.rst | 231 +++++++++++++++----------- 1 file changed, 136 insertions(+), 95 deletions(-) diff --git a/docs/how-to/using-rocprof-sys-api.rst b/docs/how-to/using-rocprof-sys-api.rst index 7de4c11c99..55b87297ee 100644 --- a/docs/how-to/using-rocprof-sys-api.rst +++ b/docs/how-to/using-rocprof-sys-api.rst @@ -174,12 +174,12 @@ CMake g++ compilation ------------------------------------------------------- -Assuming ROCm Systems Profiler is installed in ``/opt/rocprofiler-systems``, use the ``g++`` compiler +Assuming ROCm Systems Profiler is installed in ``/opt/rocprofsys``, use the ``g++`` compiler to build the application. .. code-block:: shell - g++ -I/opt/rocprofiler-systems foo.cpp -o foo -lrocprofiler-systems-user + g++ -g -I/opt/rocprofsys/include -L/opt/rocprofsys/lib foo.cpp -o foo -lrocprof-sys-user Output from the API example program ======================================== @@ -188,108 +188,149 @@ First, instrument and run the program. .. code-block:: shell-session - $ rocprof-sys-instrument -l --min-instructions=8 -E custom_push_region -o -- ./user-api + $ rocprof-sys-instrument -l --min-instructions=8 -E custom_push_region -o user-api.inst -- ./user-api ... - $ rocprof-sys-run --profile --use-pid off --time-output off -- ./user-api.inst 20 4 100 + $ rocprof-sys-run --profile --trace -- ./user-api.inst 10 12 1000 + + ROCPROFSYS: HSA_TOOLS_LIB=/opt/rocm-6.3.1/lib/librocprof-sys-dl.so.0.1.0 + ROCPROFSYS: HSA_TOOLS_REPORT_LOAD_FAILURE=1 + ROCPROFSYS: LD_PRELOAD=/opt/rocm-6.3.1/lib/librocprof-sys-dl.so.0.1.0 + ROCPROFSYS: OMP_TOOL_LIBRARIES=/opt/rocm-6.3.1/lib/librocprof-sys-dl.so.0.1.0 + ROCPROFSYS: ROCPROFSYS_PROFILE=true + ROCPROFSYS: ROCPROFSYS_TRACE=true + ROCPROFSYS: ROCPROFSYS_VERBOSE=0 + ROCPROFSYS: ROCP_HSA_INTERCEPT=1 + ROCPROFSYS: ROCP_TOOL_LIB=/opt/rocm-6.3.1/lib/librocprof-sys.so.0.1.0 + [rocprof-sys][dl][297646] rocprofsys_main + [rocprof-sys][297646][rocprofsys_init_tooling] Instrumentation mode: Trace + + + ____ ___ ____ __ __ ______ ______ _____ _____ __ __ ____ ____ ____ ___ _____ ___ _ _____ ____ + | _ \ / _ \ / ___| \/ | / ___\ \ / / ___|_ _| ____| \/ / ___| | _ \| _ \ / _ \| ___|_ _| | | ____| _ \ + | |_) | | | | | | |\/| | \___ \\ V /\___ \ | | | _| | |\/| \___ \ | |_) | |_) | | | | |_ | || | | _| | |_) | + | _ <| |_| | |___| | | | ___) || | ___) || | | |___| | | |___) | | __/| _ <| |_| | _| | || |___| |___| _ < + |_| \_\\___/ \____|_| |_| |____/ |_| |____/ |_| |_____|_| |_|____/ |_| |_| \_\\___/|_| |___|_____|_____|_| \_\ + + rocprof-sys v0.1.0 (rev: b569c837e455f71dd76d06392d0b901ae927deca, x86_64-linux-gnu, compiler: GNU v11.4.0, rocm: v6.3.x) + [105.947] perfetto.cc:47606 Configured tracing session 1, #sources:1, duration:0 ms, #buffers:1, total buffer size:1024000 KB, total sessions:1, uid:0 session name: "" Pushing custom region :: ./user-api.inst - [rocprof-sys][rocprofsys_init_tooling] Instrumentation mode: Trace - - - __ - _ __ ___ ___ _ __ _ __ ___ / _| ___ _ _ ___ - | '__| / _ \ / __| | '_ \ | '__| / _ \ | |_ _____ / __| | | | | / __| - | | | (_) | | (__ | |_) | | | | (_) | | _| |_____| \__ \ | |_| | \__ \ - |_| \___/ \___| | .__/ |_| \___/ |_| |___/ \__, | |___/ - |_| |___/ - - - Pushing custom region :: initialization - [./user-api.inst] Threads: 4 - [./user-api.inst] Iterations: 100 - [./user-api.inst] fibonacci(20)... + [./user-api.inst] Threads: 12 + [./user-api.inst] Iterations: 1000 + [./user-api.inst] fibonacci(10)... Pushing custom region :: thread_creation + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 + Pushing custom region :: run(10) x 1000 Pushing custom region :: thread_wait - Pushing custom region :: run(20) x 100 - Pushing custom region :: run(20) x 100 - Pushing custom region :: run(20) x 100 - Pushing custom region :: run(20) x 100 - Pushing custom region :: run(20) x 100 - [./user-api.inst] fibonacci(20) x 4 = 3382500 - [rocprof-sys][86267][0][rocprofsys_finalize] finalizing... + Pushing custom region :: run(10) x 1000 + [./user-api.inst] fibonacci(10) x 12 = 715000 - - [rocprof-sys][86267][0] rocprof-sys : 5.190895 sec wall_clock, 2.748 mb peak_rss, 6.330000 sec cpu_clock, 121.9 % cpu_util [laps: 1] - [rocprof-sys][86267][0] user-api.inst/thread-0 : 5.078713 sec wall_clock, 4.722415 sec thread_cpu_clock, 93.0 % thread_cpu_util, 1.276 mb peak_rss [laps: 1] - [rocprof-sys][86267][0] user-api.inst/thread-1 : 0.322248 sec wall_clock, 0.322191 sec thread_cpu_clock, 100.0 % thread_cpu_util, 1.000 mb peak_rss [laps: 1] - [rocprof-sys][86267][0] user-api.inst/thread-2 : 0.323255 sec wall_clock, 0.323194 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.000 mb peak_rss [laps: 1] - [rocprof-sys][86267][0] user-api.inst/thread-3 : 0.323569 sec wall_clock, 0.323484 sec thread_cpu_clock, 100.0 % thread_cpu_util, 1.092 mb peak_rss [laps: 1] - [rocprof-sys][86267][0] user-api.inst/thread-4 : 0.324178 sec wall_clock, 0.324057 sec thread_cpu_clock, 100.0 % thread_cpu_util, 1.184 mb peak_rss [laps: 1] - [rocprof-sys][86267][0] Post-processing 51 cpu frequency and memory usage entries... - - [rocprof-sys][wall_clock]|0> Outputting 'rocprof-sys-user-api.inst-output/wall_clock.json'... - [rocprof-sys][wall_clock]|0> Outputting 'rocprof-sys-user-api.inst-output/wall_clock.tree.json'... - [rocprof-sys][wall_clock]|0> Outputting 'rocprof-sys-user-api.inst-output/wall_clock.txt'... - - [rocprof-sys][manager::finalize][metadata]> Outputting 'rocprof-sys-user-api.inst-output/metadata.json' and 'rocprof-sys-user-api.inst-output/functions.json'... - [rocprof-sys][86267][0][rocprofsys_finalize] Finalized + [rocprof-sys][297646][0][rocprofsys_finalize] finalizing... + [rocprof-sys][297646][0][rocprofsys_finalize] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646 : 0.978014 sec wall_clock, 26.752 MB peak_rss, 27.394 MB page_rss, 1.520000 sec cpu_clock, 155.4 % cpu_util [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/0 : 0.976068 sec wall_clock, 0.789948 sec thread_cpu_clock, 80.9 % thread_cpu_util, 26.112 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/1 : 0.027517 sec wall_clock, 0.027510 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.768 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/2 : 0.027828 sec wall_clock, 0.027811 sec thread_cpu_clock, 99.9 % thread_cpu_util, 3.584 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/3 : 0.027585 sec wall_clock, 0.027585 sec thread_cpu_clock, 100.0 % thread_cpu_util, 3.584 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/4 : 0.033449 sec wall_clock, 0.033443 sec thread_cpu_clock, 100.0 % thread_cpu_util, 3.584 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/5 : 0.027727 sec wall_clock, 0.027726 sec thread_cpu_clock, 100.0 % thread_cpu_util, 3.328 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/6 : 0.032228 sec wall_clock, 0.032220 sec thread_cpu_clock, 100.0 % thread_cpu_util, 3.712 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/7 : 0.030201 sec wall_clock, 0.030202 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.768 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/8 : 0.027960 sec wall_clock, 0.027951 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.640 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/9 : 0.034698 sec wall_clock, 0.034699 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.640 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/10 : 0.033414 sec wall_clock, 0.033399 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.512 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/11 : 0.028161 sec wall_clock, 0.028149 sec thread_cpu_clock, 100.0 % thread_cpu_util, 0.384 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] rocprofsys/process/297646/thread/12 : 0.027791 sec wall_clock, 0.027767 sec thread_cpu_clock, 99.9 % thread_cpu_util, 0.256 MB peak_rss [laps: 1] + [rocprof-sys][297646][0][rocprofsys_finalize] + [rocprof-sys][297646][0][rocprofsys_finalize] Finalizing perfetto... + [rocprofiler-systems][297646][perfetto]> Outputting '/home/gliff/opt/user-api-test/rocprofsys-user-api.inst-output/2025-01-02_19.29/perfetto-trace-297646.proto' (16728.58 KB / 16.73 MB / 0.02 GB)... Done + [rocprofiler-systems][297646][wall_clock]> Outputting 'rocprofsys-user-api.inst-output/2025-01-02_19.29/wall_clock-297646.json' + [rocprofiler-systems][297646][wall_clock]> Outputting 'rocprofsys-user-api.inst-output/2025-01-02_19.29/wall_clock-297646.txt' + [rocprofiler-systems][297646][roctracer]> Outputting 'rocprofsys-user-api.inst-output/2025-01-02_19.29/roctracer-297646.json' + [rocprofiler-systems][297646][roctracer]> Outputting 'rocprofsys-user-api.inst-output/2025-01-02_19.29/roctracer-297646.txt' + [rocprofiler-systems][297646][metadata]> Outputting 'rocprofsys-user-api.inst-output/2025-01-02_19.29/metadata-297646.json' and 'rocprofsys-user-api.inst-output/2025-01-02_19.29/functions-297646.json' + [rocprof-sys][297646][0][rocprofsys_finalize] Finalized: 0.314368 sec wall_clock, 19.040 MB peak_rss, 3.498 MB page_rss, 0.280000 sec cpu_clock, 89.1 % cpu_util + [107.243] perfetto.cc:49204 Tracing session 1 ended, total sessions:0 Then review the output. .. code-block:: shell $ cat rocprof-sys-example-output/wall_clock.txt - |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| - | REAL-CLOCK TIMER (I.E. WALL-CLOCK TIMER) | - |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| - | LABEL | COUNT | DEPTH | METRIC | UNITS | SUM | MEAN | MIN | MAX | VAR | STDDEV | % SELF | - |---------------------------------------------------------------------------------|--------|--------|------------|--------|----------|----------|----------|----------|----------|----------|--------| - | |0>>> ./user-api.inst | 1 | 0 | wall_clock | sec | 5.078521 | 5.078521 | 5.078521 | 5.078521 | 0.000000 | 0.000000 | 0.0 | - | |0>>> |_initialization | 1 | 1 | wall_clock | sec | 0.000004 | 0.000004 | 0.000004 | 0.000004 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_thread_creation | 1 | 1 | wall_clock | sec | 0.000159 | 0.000159 | 0.000159 | 0.000159 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_thread_wait | 1 | 1 | wall_clock | sec | 0.355307 | 0.355307 | 0.355307 | 0.355307 | 0.000000 | 0.000000 | 0.0 | - | |0>>> |_std::vector >::begin | 1 | 2 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::vector >::end | 1 | 2 | wall_clock | sec | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_pthread_join | 4 | 2 | wall_clock | sec | 0.355257 | 0.088814 | 0.000001 | 0.333144 | 0.026559 | 0.162970 | 100.0 | - | |2>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.000032 | 0.000032 | 0.000032 | 0.000032 | 0.000000 | 0.000000 | 100.0 | - | |1>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.000036 | 0.000036 | 0.000036 | 0.000036 | 0.000000 | 0.000000 | 100.0 | - | |3>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.000034 | 0.000034 | 0.000034 | 0.000034 | 0.000000 | 0.000000 | 100.0 | - | |4>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.000039 | 0.000039 | 0.000039 | 0.000039 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_run | 1 | 1 | wall_clock | sec | 4.722993 | 4.722993 | 4.722993 | 4.722993 | 0.000000 | 0.000000 | 0.0 | - | |0>>> |_std::char_traits::length | 1 | 2 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::distance | 1 | 2 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::operator+, std::allocator > | 2 | 2 | wall_clock | sec | 0.000002 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_run(20) x 100 | 1 | 2 | wall_clock | sec | 4.722951 | 4.722951 | 4.722951 | 4.722951 | 0.000000 | 0.000000 | 0.0 | - | |0>>> |_run [{94,25}-{96,25}] | 1 | 3 | wall_clock | sec | 4.722925 | 4.722925 | 4.722925 | 4.722925 | 0.000000 | 0.000000 | 0.0 | - | |0>>> |_fib | 100 | 4 | wall_clock | sec | 4.722718 | 0.047227 | 0.046713 | 0.051987 | 0.000000 | 0.000625 | 0.0 | - | |0>>> |_fib | 200 | 5 | wall_clock | sec | 4.722302 | 0.023612 | 0.017827 | 0.034091 | 0.000032 | 0.005627 | 0.0 | - | |0>>> |_fib | 400 | 6 | wall_clock | sec | 4.721485 | 0.011804 | 0.006790 | 0.023003 | 0.000016 | 0.004024 | 0.0 | - | |0>>> |_fib | 800 | 7 | wall_clock | sec | 4.719858 | 0.005900 | 0.002564 | 0.016078 | 0.000006 | 0.002498 | 0.1 | - | |0>>> |_fib | 1600 | 8 | wall_clock | sec | 4.716572 | 0.002948 | 0.000977 | 0.011849 | 0.000002 | 0.001465 | 0.1 | - | |0>>> |_fib | 3200 | 9 | wall_clock | sec | 4.709918 | 0.001472 | 0.000371 | 0.008246 | 0.000001 | 0.000831 | 0.3 | - | |0>>> |_fib | 6400 | 10 | wall_clock | sec | 4.696775 | 0.000734 | 0.000140 | 0.005111 | 0.000000 | 0.000461 | 0.6 | - | |0>>> |_fib | 12800 | 11 | wall_clock | sec | 4.670093 | 0.000365 | 0.000050 | 0.003166 | 0.000000 | 0.000253 | 1.1 | - | |0>>> |_fib | 25600 | 12 | wall_clock | sec | 4.617496 | 0.000180 | 0.000017 | 0.001959 | 0.000000 | 0.000137 | 2.3 | - | |0>>> |_fib | 51200 | 13 | wall_clock | sec | 4.512671 | 0.000088 | 0.000004 | 0.001212 | 0.000000 | 0.000074 | 4.6 | - | |0>>> |_fib | 102400 | 14 | wall_clock | sec | 4.304142 | 0.000042 | 0.000000 | 0.000752 | 0.000000 | 0.000039 | 9.6 | - | |0>>> |_fib | 202600 | 15 | wall_clock | sec | 3.892580 | 0.000019 | 0.000000 | 0.000469 | 0.000000 | 0.000021 | 19.0 | - | |0>>> |_fib | 363200 | 16 | wall_clock | sec | 3.151143 | 0.000009 | 0.000000 | 0.000293 | 0.000000 | 0.000011 | 33.2 | - | |0>>> |_fib | 502000 | 17 | wall_clock | sec | 2.105217 | 0.000004 | 0.000000 | 0.000183 | 0.000000 | 0.000006 | 49.1 | - | |0>>> |_fib | 476000 | 18 | wall_clock | sec | 1.071652 | 0.000002 | 0.000000 | 0.000114 | 0.000000 | 0.000004 | 63.6 | - | |0>>> |_fib | 294200 | 19 | wall_clock | sec | 0.390193 | 0.000001 | 0.000000 | 0.000071 | 0.000000 | 0.000003 | 75.3 | - | |0>>> |_fib | 115200 | 20 | wall_clock | sec | 0.096190 | 0.000001 | 0.000000 | 0.000043 | 0.000000 | 0.000002 | 84.4 | - | |0>>> |_fib | 27400 | 21 | wall_clock | sec | 0.015020 | 0.000001 | 0.000000 | 0.000025 | 0.000000 | 0.000001 | 91.1 | - | |0>>> |_fib | 3600 | 22 | wall_clock | sec | 0.001336 | 0.000000 | 0.000000 | 0.000013 | 0.000000 | 0.000001 | 96.3 | - | |0>>> |_fib | 200 | 23 | wall_clock | sec | 0.000050 | 0.000000 | 0.000000 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::char_traits::length | 1 | 3 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::distance | 1 | 3 | wall_clock | sec | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::operator+, std::allocator > | 2 | 3 | wall_clock | sec | 0.000001 | 0.000001 | 0.000000 | 0.000001 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::operator& | 1 | 1 | wall_clock | sec | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> std::vector >::~vector | 1 | 0 | wall_clock | sec | 0.000045 | 0.000045 | 0.000045 | 0.000045 | 0.000000 | 0.000000 | 32.7 | - | |0>>> |_std::thread::~thread | 4 | 1 | wall_clock | sec | 0.000030 | 0.000007 | 0.000007 | 0.000009 | 0.000000 | 0.000001 | 31.2 | - | |0>>> |_std::thread::joinable | 4 | 2 | wall_clock | sec | 0.000021 | 0.000005 | 0.000005 | 0.000006 | 0.000000 | 0.000001 | 89.4 | - | |0>>> |_std::thread::id::id | 4 | 3 | wall_clock | sec | 0.000001 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::operator== | 4 | 3 | wall_clock | sec | 0.000001 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::allocator_traits >::deallocate | 1 | 1 | wall_clock | sec | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - | |0>>> |_std::allocator::~allocator | 1 | 1 | wall_clock | sec | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 0.000000 | 100.0 | - |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| + |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| + | REAL-CLOCK TIMER (I.E. WALL-CLOCK TIMER) | + |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| + | LABEL | COUNT | DEPTH | METRIC | UNITS | SUM | MEAN | MIN | MAX | VAR | STDDEV | % SELF | + |---------------------------------------------------------------------------------------------------------|--------|--------|------------|--------|----------|----------|----------|----------|----------|----------|--------| + | |00>>> ./user-api.inst | 1 | 0 | wall_clock | sec | 0.874293 | 0.874293 | 0.874293 | 0.874293 | 0.000000 | 0.000000 | 0.0 | + | |00>>> |_initialization | 1 | 1 | wall_clock | sec | 0.000015 | 0.000015 | 0.000015 | 0.000015 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_thread_creation | 1 | 1 | wall_clock | sec | 0.059934 | 0.059934 | 0.059934 | 0.059934 | 0.000000 | 0.000000 | 1.0 | + | |00>>> |_pthread_create | 12 | 2 | wall_clock | sec | 0.059338 | 0.004945 | 0.004455 | 0.005743 | 0.000000 | 0.000479 | 0.0 | + | |01>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027499 | 0.027499 | 0.027499 | 0.027499 | 0.000000 | 0.000000 | 0.1 | + | |01>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027463 | 0.027463 | 0.027463 | 0.027463 | 0.000000 | 0.000000 | 100.0 | + | |02>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027804 | 0.027804 | 0.027804 | 0.027804 | 0.000000 | 0.000000 | 0.2 | + | |02>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027752 | 0.027752 | 0.027752 | 0.027752 | 0.000000 | 0.000000 | 100.0 | + | |03>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027567 | 0.027567 | 0.027567 | 0.027567 | 0.000000 | 0.000000 | 0.1 | + | |03>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027529 | 0.027529 | 0.027529 | 0.027529 | 0.000000 | 0.000000 | 100.0 | + | |05>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027699 | 0.027699 | 0.027699 | 0.027699 | 0.000000 | 0.000000 | 0.2 | + | |05>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027651 | 0.027651 | 0.027651 | 0.027651 | 0.000000 | 0.000000 | 100.0 | + | |04>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.033427 | 0.033427 | 0.033427 | 0.033427 | 0.000000 | 0.000000 | 0.2 | + | |04>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.033376 | 0.033376 | 0.033376 | 0.033376 | 0.000000 | 0.000000 | 100.0 | + | |06>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.032210 | 0.032210 | 0.032210 | 0.032210 | 0.000000 | 0.000000 | 0.1 | + | |06>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.032168 | 0.032168 | 0.032168 | 0.032168 | 0.000000 | 0.000000 | 100.0 | + | |07>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.030176 | 0.030176 | 0.030176 | 0.030176 | 0.000000 | 0.000000 | 0.2 | + | |07>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.030122 | 0.030122 | 0.030122 | 0.030122 | 0.000000 | 0.000000 | 100.0 | + | |08>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027941 | 0.027941 | 0.027941 | 0.027941 | 0.000000 | 0.000000 | 0.1 | + | |08>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027899 | 0.027899 | 0.027899 | 0.027899 | 0.000000 | 0.000000 | 100.0 | + | |09>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.034679 | 0.034679 | 0.034679 | 0.034679 | 0.000000 | 0.000000 | 0.1 | + | |09>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.034636 | 0.034636 | 0.034636 | 0.034636 | 0.000000 | 0.000000 | 100.0 | + | |11>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.028143 | 0.028143 | 0.028143 | 0.028143 | 0.000000 | 0.000000 | 0.1 | + | |11>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.028103 | 0.028103 | 0.028103 | 0.028103 | 0.000000 | 0.000000 | 100.0 | + | |10>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.033393 | 0.033393 | 0.033393 | 0.033393 | 0.000000 | 0.000000 | 0.1 | + | |10>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.033354 | 0.033354 | 0.033354 | 0.033354 | 0.000000 | 0.000000 | 100.0 | + | |12>>> |_start_thread | 1 | 3 | wall_clock | sec | 0.027765 | 0.027765 | 0.027765 | 0.027765 | 0.000000 | 0.000000 | 0.2 | + | |12>>> |_run(10) x 1000 | 1 | 4 | wall_clock | sec | 0.027710 | 0.027710 | 0.027710 | 0.027710 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_thread_wait | 1 | 1 | wall_clock | sec | 0.027971 | 0.027971 | 0.027971 | 0.027971 | 0.000000 | 0.000000 | 1.3 | + | |00>>> |_std::vector >::begin | 1 | 2 | wall_clock | sec | 0.000003 | 0.000003 | 0.000003 | 0.000003 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::vector >::end | 1 | 2 | wall_clock | sec | 0.000002 | 0.000002 | 0.000002 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |___gnu_cxx::operator!= > > | 13 | 2 | wall_clock | sec | 0.000024 | 0.000002 | 0.000001 | 0.000003 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_pthread_join | 12 | 2 | wall_clock | sec | 0.027583 | 0.002299 | 0.000003 | 0.011250 | 0.000011 | 0.003289 | 100.0 | + | |00>>> |_run | 1 | 1 | wall_clock | sec | 0.786236 | 0.786236 | 0.786236 | 0.786236 | 0.000000 | 0.000000 | 0.0 | + | |00>>> |_std::char_traits::length | 1 | 2 | wall_clock | sec | 0.000002 | 0.000002 | 0.000002 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::distance | 1 | 2 | wall_clock | sec | 0.000002 | 0.000002 | 0.000002 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::operator+, std::allocator > | 4 | 2 | wall_clock | sec | 0.000006 | 0.000002 | 0.000001 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_run(10) x 1000 | 1 | 2 | wall_clock | sec | 0.786184 | 0.786184 | 0.786184 | 0.786184 | 0.000000 | 0.000000 | 0.0 | + | |00>>> |_run [{95,25}-{97,25}] | 1 | 3 | wall_clock | sec | 0.786141 | 0.786141 | 0.786141 | 0.786141 | 0.000000 | 0.000000 | 0.4 | + | |00>>> |_fib | 1000 | 4 | wall_clock | sec | 0.782692 | 0.000783 | 0.000757 | 0.001397 | 0.000000 | 0.000026 | 1.0 | + | |00>>> |_fib | 2000 | 5 | wall_clock | sec | 0.774875 | 0.000387 | 0.000282 | 0.000863 | 0.000000 | 0.000095 | 2.0 | + | |00>>> |_fib | 4000 | 6 | wall_clock | sec | 0.759351 | 0.000190 | 0.000101 | 0.000570 | 0.000000 | 0.000068 | 4.0 | + | |00>>> |_fib | 8000 | 7 | wall_clock | sec | 0.728911 | 0.000091 | 0.000034 | 0.000350 | 0.000000 | 0.000042 | 8.5 | + | |00>>> |_fib | 16000 | 8 | wall_clock | sec | 0.666793 | 0.000042 | 0.000009 | 0.000206 | 0.000000 | 0.000025 | 18.5 | + | |00>>> |_fib | 32000 | 9 | wall_clock | sec | 0.543524 | 0.000017 | 0.000001 | 0.000121 | 0.000000 | 0.000014 | 38.3 | + | |00>>> |_fib | 52000 | 10 | wall_clock | sec | 0.335118 | 0.000006 | 0.000001 | 0.000070 | 0.000000 | 0.000008 | 61.0 | + | |00>>> |_fib | 44000 | 11 | wall_clock | sec | 0.130629 | 0.000003 | 0.000001 | 0.000036 | 0.000000 | 0.000004 | 79.4 | + | |00>>> |_fib | 16000 | 12 | wall_clock | sec | 0.026893 | 0.000002 | 0.000001 | 0.000026 | 0.000000 | 0.000002 | 91.5 | + | |00>>> |_fib | 2000 | 13 | wall_clock | sec | 0.002279 | 0.000001 | 0.000001 | 0.000014 | 0.000000 | 0.000001 | 100.0 | + | |00>>> |_std::char_traits::length | 1 | 3 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::distance | 1 | 3 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::operator+, std::allocator > | 4 | 3 | wall_clock | sec | 0.000005 | 0.000001 | 0.000001 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::operator& | 1 | 1 | wall_clock | sec | 0.000003 | 0.000003 | 0.000003 | 0.000003 | 0.000000 | 0.000000 | 100.0 | + | |00>>> std::vector >::~vector | 1 | 0 | wall_clock | sec | 0.000256 | 0.000256 | 0.000256 | 0.000256 | 0.000000 | 0.000000 | 20.9 | + | |00>>> |_std::thread::~thread | 12 | 1 | wall_clock | sec | 0.000193 | 0.000016 | 0.000014 | 0.000025 | 0.000000 | 0.000004 | 31.9 | + | |00>>> |_std::thread::joinable | 12 | 2 | wall_clock | sec | 0.000131 | 0.000011 | 0.000010 | 0.000017 | 0.000000 | 0.000003 | 77.6 | + | |00>>> |_std::thread::id::id | 12 | 3 | wall_clock | sec | 0.000016 | 0.000001 | 0.000001 | 0.000004 | 0.000000 | 0.000001 | 100.0 | + | |00>>> |_std::operator== | 12 | 3 | wall_clock | sec | 0.000014 | 0.000001 | 0.000001 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::allocator_traits >::deallocate | 1 | 1 | wall_clock | sec | 0.000008 | 0.000008 | 0.000008 | 0.000008 | 0.000000 | 0.000000 | 70.8 | + | |00>>> |___gnu_cxx::new_allocator::deallocate | 1 | 2 | wall_clock | sec | 0.000002 | 0.000002 | 0.000002 | 0.000002 | 0.000000 | 0.000000 | 100.0 | + | |00>>> |_std::allocator::~allocator | 1 | 1 | wall_clock | sec | 0.000001 | 0.000001 | 0.000001 | 0.000001 | 0.000000 | 0.000000 | 100.0 | + |----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|