Sign Up
Log In
Log In
or
Sign Up
Places
All Projects
Status Monitor
Collapse sidebar
home:Ledest:erlang:25
erlang
4391-Rename-hprof-to-tprof.patch
Overview
Repositories
Revisions
Requests
Users
Attributes
Meta
File 4391-Rename-hprof-to-tprof.patch of Package erlang
From 5c7e265dd29db711d9271454ce7e380207cc8f9a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= <jose.valim@dashbit.co> Date: Mon, 16 Oct 2023 12:11:42 +0200 Subject: [PATCH] Rename hprof to tprof Instead of having 4 profilers with 4 different APIs, this pull request unifies call, time, and memory profiling under a single module. --- lib/tools/doc/src/Makefile | 2 +- lib/tools/doc/src/ref_man.xml | 6 +- lib/tools/doc/src/specs.xml | 2 +- lib/tools/doc/src/{hprof.xml => tprof.xml} | 373 ++++++++++-------- lib/tools/src/Makefile | 2 +- lib/tools/src/{hprof.erl => tprof.erl} | 329 ++++++++------- lib/tools/test/Makefile | 2 +- .../test/{hprof_SUITE.erl => tprof_SUITE.erl} | 242 ++++++++---- system/doc/efficiency_guide/profiling.xml | 17 +- .../upcoming_incompatibilities.xml | 10 + 10 files changed, 575 insertions(+), 410 deletions(-) rename lib/tools/doc/src/{hprof.xml => tprof.xml} (61%) rename lib/tools/src/{hprof.erl => tprof.erl} (66%) rename lib/tools/test/{hprof_SUITE.erl => tprof_SUITE.erl} (52%) diff --git a/lib/tools/doc/src/Makefile b/lib/tools/doc/src/Makefile index 18e51cc51f..9fdb5a56d6 100644 --- a/lib/tools/doc/src/Makefile +++ b/lib/tools/doc/src/Makefile @@ -35,7 +35,7 @@ XML_APPLICATION_FILES = ref_man.xml XML_REF3_FILES = \ cover.xml \ eprof.xml \ - hprof.xml \ + tprof.xml \ fprof.xml \ cprof.xml \ lcnt.xml \ diff --git a/lib/tools/doc/src/ref_man.xml b/lib/tools/doc/src/ref_man.xml index 1fe9c6e261..98e8cc6299 100644 --- a/lib/tools/doc/src/ref_man.xml +++ b/lib/tools/doc/src/ref_man.xml @@ -52,8 +52,8 @@ Erlang programs. Uses trace to file to minimize runtime performance impact, and displays time for calling and called functions.</item> - <tag><em>hprof</em></tag> - <item>A heap profiling tool; measures how much heap space is + <tag><em>tprof</em></tag> + <item>A tracing profiling tool; measures how much time or heap space is allocated by Erlang processes.</item> <tag><em>lcnt</em></tag> @@ -74,7 +74,7 @@ <xi:include href="eprof.xml"/> <xi:include href="erlang_mode.xml"/> <xi:include href="fprof.xml"/> - <xi:include href="hprof.xml"/> + <xi:include href="tprof.xml"/> <xi:include href="lcnt.xml"/> <xi:include href="make.xml"/> <xi:include href="tags.xml"/> diff --git a/lib/tools/doc/src/specs.xml b/lib/tools/doc/src/specs.xml index d7e1002a6c..4a1db0cdfe 100644 --- a/lib/tools/doc/src/specs.xml +++ b/lib/tools/doc/src/specs.xml @@ -5,7 +5,7 @@ <xi:include href="../specs/specs_make.xml"/> <xi:include href="../specs/specs_lcnt.xml"/> <xi:include href="../specs/specs_eprof.xml"/> - <xi:include href="../specs/specs_hprof.xml"/> + <xi:include href="../specs/specs_tprof.xml"/> <xi:include href="../specs/specs_tags.xml"/> <xi:include href="../specs/specs_cover.xml"/> <xi:include href="../specs/specs_xref.xml"/> diff --git a/lib/tools/doc/src/hprof.xml b/lib/tools/doc/src/tprof.xml similarity index 61% rename from lib/tools/doc/src/hprof.xml rename to lib/tools/doc/src/tprof.xml index f01fd8f5d3..2a30406a6e 100644 --- a/lib/tools/doc/src/hprof.xml +++ b/lib/tools/doc/src/tprof.xml @@ -24,30 +24,47 @@ </legalnotice> - <title>hprof</title> + <title>tprof</title> <prepared>maximfca@gmail.com</prepared> <docno></docno> <date></date> <rev></rev> </header> - <module since="OTP 27.0">hprof</module> - <modulesummary>Process Heap Profiling Tool</modulesummary> + <module since="OTP 27.0">tprof</module> + <modulesummary>Process Tracing Profiling Tool</modulesummary> <description> - <p><c>hprof</c> provides convenience helpers for Erlang process heap + <p><c>tprof</c> provides convenience helpers for Erlang process profiling. Underlying mechanism is the Erlang trace BIFs.</p> - <p>Heap profiling can be done ad-hoc, to understand heap allocations - done by your program, or run in a server-aided mode for deeper - introspection of the code running in production.</p> + <warning><p> + This module aims to replace <c>eprof</c> and <c>cprof</c> + into a unified API for measuring call count, time, and allocation. + It is experimental in Erlang/OTP 27.0. + </p></warning> + + <p>It is possible to analyze the number of calls, the time spent + by function, and heap allocations by function. Profiling can + be done ad-hoc or run in a server-aided mode for deeper introspection + of the code running in production.</p> <warning><p> Avoid hot code reload for modules that are participating in - the memory tracing. Reloading a module turns tracing off, - discarding accumulated statistics. <c>hprof</c> + the tracing. Reloading a module turns tracing off, + discarding accumulated statistics. <c>tprof</c> may not report correct amounts when code reload happened during profiling session. </p></warning> + <p>The <c>type</c> option controls which type of profiling + to perform. You can choose between <c>call_count</c>, + <c>call_time</c>, and <c>call_memory</c>. The default is + <c>call_count</c>, it has the smallest footprint on the + system but it does not support per-process profiling. + For this reason, all of the examples below use + <c>call_memory</c>, which measures heap allocation, and + provide a more complex feature set to demonstrate. + </p> + <p>Heap allocations happen for all Erlang terms that do not fit a single machine word. For example, a function returning tuple of 2 elements needs to allocate this tuple on the process heap. @@ -58,7 +75,7 @@ <p>When profiling is enabled, expect a slowdown in the program execution.</p> <p> - For profiling convenience, heap allocations are accumulated for + For profiling convenience, measurements are accumulated for functions that are not enabled in trace pattern. Consider this call stack example:</p> <code type="none"><![CDATA[ @@ -83,11 +100,11 @@ </p> <code type="none"><![CDATA[ - 1> hprof:profile(lists, seq, [1, 16]). + 1> tprof:profile(lists, seq, [1, 16], #{type => call_memory}). ****** Process <0.179.0> -- 100.00 % of total allocations *** - MODUL FUN/ARITY CALLS WORDS PER CALL [ %] - lists seq_loop/3 5 32 6 [100.00] + FUNCTION CALLS WORDS PER CALL [ %] + lists:seq_loop/3 5 32 6 [100.00] 32 [ 100.0] ok ]]></code> @@ -100,23 +117,24 @@ </p> <code type="none"><![CDATA[ - 1> hprof:profile(fun() -> lists:seq(1, 16) end). + 1> tprof:profile(fun() -> lists:seq(1, 16) end, #{type => call_memory}). ****** Process <0.224.0> -- 100.00 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - erl_eval match_list/6 1 3 3 [ 3.19] - erl_eval do_apply/7 1 3 3 [ 3.19] - lists reverse/1 1 4 4 [ 4.26] - erl_eval add_bindings/2 1 5 5 [ 5.32] - erl_eval expr_list/7 3 7 2 [ 7.45] - erl_eval ret_expr/3 4 16 4 [17.02] - erl_eval merge_bindings/4 3 24 8 [25.53] - lists seq_loop/3 5 32 6 [34.04] - - 2> hprof:profile(fun() -> lists:seq(1, 16) end, #{pattern => [{lists, seq_loop, '_'}]}). + FUNCTION CALLS WORDS PER CALL [ %] + erl_eval:match_list/6 1 3 3 [ 3.19] + erl_eval:do_apply/7 1 3 3 [ 3.19] + lists:reverse/1 1 4 4 [ 4.26] + erl_eval:add_bindings/2 1 5 5 [ 5.32] + erl_eval:expr_list/7 3 7 2 [ 7.45] + erl_eval:ret_expr/3 4 16 4 [17.02] + erl_eval:merge_bindings/4 3 24 8 [25.53] + lists:seq_loop/3 5 32 6 [34.04] + + 2> tprof:profile(fun() -> lists:seq(1, 16) end, + #{type => call_memory, pattern => [{lists, seq_loop, '_'}]}). ****** Process <0.247.0> -- 100.00 % of total allocations *** - MODUL FUN/ARITY CALLS WORDS PER CALL [ %] - lists seq_loop/3 5 32 6 [100.00] + FUNCTION CALLS WORDS PER CALL [ %] + lists:seq_loop/3 5 32 6 [100.00] ]]></code> <p> @@ -137,115 +155,124 @@ <p>Default format prints per-process statistics.</p> <code type="none"><![CDATA[ - 2> hprof:profile(test, test_spawn, []). + 2> tprof:profile(test, test_spawn, [], #{type => call_memory}). ****** Process <0.176.0> -- 23.66 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - erlang spawn_monitor/1 1 2 2 [ 9.09] - erlang spawn_opt/4 1 6 6 [27.27] - test test_spawn/0 1 14 14 [63.64] + FUNCTION CALLS WORDS PER CALL [ %] + erlang:spawn_monitor/1 1 2 2 [ 9.09] + erlang:spawn_opt/4 1 6 6 [27.27] + test:test_spawn/0 1 14 14 [63.64] 22 [100.0] ****** Process <0.177.0> -- 76.34 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - erlang apply/2 1 7 7 [ 9.86] - lists seq_loop/3 9 64 7 [90.14] + FUNCTION CALLS WORDS PER CALL [ %] + erlang:apply/2 1 7 7 [ 9.86] + lists:seq_loop/3 9 64 7 [90.14] 71 [100.0] ]]></code> <p>This example prints the combined memory allocation of all processes, sorted by total allocated words in the descending order</p> <code type="none"><![CDATA[ - 5> hprof:profile(test, test_spawn, [], #{report => {total, {words, descending}}}). - - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - lists seq_loop/3 9 64 7 [68.82] - test test_spawn/0 1 14 14 [15.05] - erlang apply/2 1 7 7 [ 7.53] - erlang spawn_opt/4 1 6 6 [ 6.45] - erlang spawn_monitor/1 1 2 2 [ 2.15] + 5> tprof:profile(test, test_spawn, [], + #{type => call_memory, report => {total, {words, descending}}}). + + FUNCTION CALLS WORDS PER CALL [ %] + lists:seq_loop/3 9 64 7 [68.82] + test:test_spawn/0 1 14 14 [15.05] + erlang:apply/2 1 7 7 [ 7.53] + erlang:spawn_opt/4 1 6 6 [ 6.45] + erlang:spawn_monitor/1 1 2 2 [ 2.15] 93 [100.0] ]]></code> <p>You can also collect the profile for further inspection.</p> <code type="none"><![CDATA[ - 6> {done, ProfileData} = hprof:profile(fun test:test_spawn/0, #{report => return}). + 6> {done, ProfileData} = tprof:profile(fun test:test_spawn/0, + #{type => call_memory, report => return}). <...> - 7> hprof:format(hprof:inspect(ProfileData, process, {percent, descending})). + 7> tprof:format(tprof:inspect(ProfileData, process, {percent, descending})). ****** Process <0.223.0> -- 23.66 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - test test_spawn/0 1 14 14 [63.64] - erlang spawn_opt/4 1 6 6 [27.27] - erlang spawn_monitor/1 1 2 2 [ 9.09] + FUNCTION CALLS WORDS PER CALL [ %] + test:test_spawn/0 1 14 14 [63.64] + erlang:spawn_opt/4 1 6 6 [27.27] + erlang:spawn_monitor/1 1 2 2 [ 9.09] 22 [100.0] ****** Process <0.224.0> -- 76.34 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - lists seq_loop/3 9 64 7 [90.14] - erlang apply/2 1 7 7 [ 9.86] + FUNCTION CALLS WORDS PER CALL [ %] + lists:seq_loop/3 9 64 7 [90.14] + erlang:apply/2 1 7 7 [ 9.86] 71 [100.0] ]]></code> <p> - By default, basic profiling takes into account all processes spawned - from the user-provided function (using <c>set_on_spawn</c> argument for - trace/3 BIF). You can limit the trace to a single process: + The processes which are profiled depends on the profiling type. + <c>call_count</c>, the default, will count calls across all processes. + The other types, <c>call_time</c> and <c>call_memory</c>, take into + account all processes spawned from the user-provided function + (using <c>set_on_spawn</c> argument for trace/3 BIF). You cannot restrict + the profiled processes for <c>call_count</c>, but you can limit the trace + to a single process for the other two: </p> <code type="none"><![CDATA[ - 2> hprof:profile(test, test_spawn, [], #{set_on_spawn => false}). + 2> tprof:profile(test, test_spawn, [], + #{type => call_memory, set_on_spawn => false}). ****** Process <0.183.0> -- 100.00 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - erlang spawn_monitor/1 1 2 2 [ 9.09] - erlang spawn_opt/4 1 6 6 [27.27] - test test_spawn/0 1 14 14 [63.64] + FUNCTION CALLS WORDS PER CALL [ %] + erlang:spawn_monitor/1 1 2 2 [ 9.09] + erlang:spawn_opt/4 1 6 6 [27.27] + test:test_spawn/0 1 14 14 [63.64] ]]></code> <marker id="pg_example"/> <p> - Erlang programs may perform memory-intensive operations in processes - that are different from the original one. You can include multiple, new or - even all processes in the trace. + Erlang programs may perform expensive operations in processes + that are different from the original one. You can include + multiple, new or even all processes in the trace when measuring + time or memory: </p> <code type="none"><![CDATA[ 7> pg:start_link(). {ok,<0.252.0>} - 8> hprof:profile(fun () -> pg:join(group, self()) end, #{rootset => [pg]}). + 8> tprof:profile(fun() -> pg:join(group, self()) end, + #{type => call_memory, rootset => [pg]}). ****** Process <0.252.0> -- 52.86 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - pg leave_local_update_ets/5 1 2 2 [ 1.80] - gen reply/2 1 3 3 [ 2.70] - erlang monitor/2 1 3 3 [ 2.70] - gen_server try_handle_call/4 1 3 3 [ 2.70] - gen_server try_dispatch/4 1 3 3 [ 2.70] - maps iterator/1 2 4 2 [ 3.60] - maps take/2 1 6 6 [ 5.41] - pg join_local_update_ets/5 1 8 8 [ 7.21] - pg handle_info/2 1 8 8 [ 7.21] - pg handle_call/3 1 9 9 [ 8.11] - gen_server loop/7 2 9 4 [ 8.11] - ets lookup/2 2 10 5 [ 9.01] - pg join_local/3 1 11 11 [ 9.91] - pg notify_group/5 2 16 8 [14.41] - erlang setelement/3 2 16 8 [14.41] + FUNCTION CALLS WORDS PER CALL [ %] + pg:leave_local_update_ets/5 1 2 2 [ 1.80] + gen:reply/2 1 3 3 [ 2.70] + erlang:monitor/2 1 3 3 [ 2.70] + gen_server:try_handle_call/4 1 3 3 [ 2.70] + gen_server:try_dispatch/4 1 3 3 [ 2.70] + maps:iterator/1 2 4 2 [ 3.60] + maps:take/2 1 6 6 [ 5.41] + pg:join_local_update_ets/5 1 8 8 [ 7.21] + pg:handle_info/2 1 8 8 [ 7.21] + pg:handle_call/3 1 9 9 [ 8.11] + gen_server:loop/7 2 9 4 [ 8.11] + ets:lookup/2 2 10 5 [ 9.01] + pg:join_local/3 1 11 11 [ 9.91] + pg:notify_group/5 2 16 8 [14.41] + erlang:setelement/3 2 16 8 [14.41] 111 [100.0] ****** Process <0.255.0> -- 47.14 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - erl_eval match_list/6 1 3 3 [ 3.03] - erlang monitor/2 1 3 3 [ 3.03] - lists reverse/1 2 4 2 [ 4.04] - pg join/3 1 4 4 [ 4.04] - erl_eval add_bindings/2 1 5 5 [ 5.05] - erl_eval do_apply/7 2 6 3 [ 6.06] - gen call/4 1 8 8 [ 8.08] - erl_eval expr_list/7 4 10 2 [10.10] - gen do_call/4 1 16 16 [16.16] - erl_eval ret_expr/3 4 16 4 [16.16] - erl_eval merge_bindings/4 3 24 8 [24.24] + FUNCTION CALLS WORDS PER CALL [ %] + erl_eval:match_list/6 1 3 3 [ 3.03] + erlang:monitor/2 1 3 3 [ 3.03] + lists:reverse/1 2 4 2 [ 4.04] + pg:join/3 1 4 4 [ 4.04] + erl_eval:add_bindings/2 1 5 5 [ 5.05] + erl_eval:do_apply/7 2 6 3 [ 6.06] + gen:call/4 1 8 8 [ 8.08] + erl_eval:expr_list/7 4 10 2 [10.10] + gen:do_call/4 1 16 16 [16.16] + erl_eval:ret_expr/3 4 16 4 [16.16] + erl_eval:merge_bindings/4 3 24 8 [24.24] 99 [100.0] ]]></code> @@ -259,7 +286,7 @@ </p> <code type="none"> - 9> hprof:profile(timer, sleep, [100000], #{timeout => 1000}). + 9> tprof:profile(timer, sleep, [100000], #{timeout => 1000}). </code> <p>By default, only one ad-hoc or server-aided profiling session is allowed @@ -269,7 +296,7 @@ </p> <code type="none"> - 1> hprof:profile(fun() -> lists:seq(1, 32) end, + 1> tprof:profile(fun() -> lists:seq(1, 32) end, #{registered => false, pattern => [{lists, '_', '_'}]}). </code> @@ -279,37 +306,37 @@ <title>Server-aided profiling</title> <p> Memory profiling can be done when your system is up and running. You - can start the <c>hprof</c> server, add trace patterns and processes + can start the <c>tprof</c> server, add trace patterns and processes to trace while your system handles actual traffic. You can extract the data any time, inspect, and print. The example below traces activity of all processes supervised by kernel: </p> <code type="none"><![CDATA[ - 1> hprof:start(). + 1> tprof:start(#{type => call_memory}). {ok,<0.200.0>} - 2> hprof:enable_trace({all_children, kernel_sup}). + 2> tprof:enable_trace({all_children, kernel_sup}). 34 - 3> hprof:set_pattern('_', '_' , '_'). + 3> tprof:set_pattern('_', '_' , '_'). 16728 - 4> Sample = hprof:collect(). + 4> Sample = tprof:collect(). [{gen_server,try_dispatch,4,[{<0.154.0>,2,6}]}, {erlang,iolist_to_iovec,1,[{<0.161.0>,1,8}]}, <...> - 5 > hprof:format(hprof:inspect(Sample)). + 5 > tprof:format(tprof:inspect(Sample)). ****** Process <0.154.0> -- 14.21 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - maps iterator/1 2 4 2 [15.38] - gen_server try_dispatch/4 2 6 3 [23.08] - net_kernel handle_info/2 2 16 8 [61.54] + FUNCTION CALLS WORDS PER CALL [ %] + maps:iterator/1 2 4 2 [15.38] + gen_server:try_dispatch/4 2 6 3 [23.08] + net_kernel:handle_info/2 2 16 8 [61.54] 26 [100.0] ****** Process <0.161.0> -- 85.79 % of total allocations *** - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] - disk_log handle/2 2 2 1 [ 1.27] - disk_log_1 maybe_start_timer/1 1 3 3 [ 1.91] - disk_log_1 mf_write_cache/1 1 3 3 [ 1.91] + FUNCTION CALLS WORDS PER CALL [ %] + disk_log:handle/2 2 2 1 [ 1.27] + disk_log_1:maybe_start_timer/1 1 3 3 [ 1.91] + disk_log_1:mf_write_cache/1 1 3 3 [ 1.91] <...> ]]></code> @@ -319,22 +346,23 @@ individual processes: </p> <code type="none"><![CDATA[ - 1> hprof:start(), hprof:enable_trace(processes), hprof:set_pattern('_', '_' , '_'). + 1> tprof:start(#{type => call_memory}). + 2> tprof:enable_trace(processes), tprof:set_pattern('_', '_' , '_'). 9041 - 2> timer:sleep(10000), hprof:disable_trace(processes), Sample = hprof:collect(). + 3> timer:sleep(10000), tprof:disable_trace(processes), Sample = tprof:collect(). [{user_drv,server,3,[{<0.64.0>,12,136}]}, {user_drv,contains_ctrl_g_or_ctrl_c,1,[{<0.64.0>,80,10}]}, <...> - 3> Inspected = hprof:inspect(Sample, process, words), Shell = maps:get(self(), Inspected). + 4> Inspected = tprof:inspect(Sample, process, words), Shell = maps:get(self(), Inspected). {2743, [{shell,{enc,0},1,2,2,0.07291286912139992}, <...> - 4> hprof:format(Shell). + 5> tprof:format(Shell). - MODULE FUN/ARITY CALLS WORDS PER CALL [ %] + FUNCTION CALLS WORDS PER CALL [ %] <...> - erl_lint start/2 2 300 150 [10.94] - shell used_records/1 114 342 3 [12.47] + erl_lint:start/2 2 300 150 [10.94] + shell:used_records/1 114 342 3 [12.47] ]]></code> </section> @@ -345,6 +373,9 @@ <p>Either process identified (pid), or a registered process name.</p> </desc> </datatype> + <datatype> + <name name="trace_type"/> + </datatype> <datatype> <name name="trace_map"/> <desc> @@ -357,7 +388,7 @@ <datatype> <name name="trace_options"/> <desc> - <p>Options for enabling heap profiling of the selected processes, + <p>Options for enabling profiling of the selected processes, see <seemfa marker="#enable_trace/2"><c>enable_trace/2</c></seemfa>.</p> </desc> </datatype> @@ -408,14 +439,14 @@ <tag><c>calls</c></tag> <item>Number of calls to the function. </item> - <tag><c>words</c></tag> - <item>Total number of words allocated throughout all calls to the function. + <tag><c>measurement</c></tag> + <item>Total measurement (call count, time, or heap allocation) throughout all calls to the function. </item> - <tag><c>words_per_call</c></tag> - <item>Number of words allocated on average per function call. + <tag><c>measurement_per_call</c></tag> + <item>Measurement (call count, time, or heap allocation) on average per function call. </item> <tag><c>percent</c></tag> - <item>Percentage of <c>words</c> to a total amount allocated during the + <item>Percentage of measurement to total amount during the entire profile collection. </item> </taglist> @@ -430,7 +461,7 @@ <desc> <p> Starts the server, not supervised. Profiling server stores current trace patterns and - ensures a single instance of heap profiler is running.</p> + ensures a single instance of profiler is running.</p> </desc> </func> <func> @@ -444,32 +475,32 @@ <name name="stop" arity="0" since="OTP 27.0"/> <fsummary>Stop profiling server.</fsummary> <desc> - <p>Stops the <c>hprof</c>, disabling memory tracing that has + <p>Stops the <c>tprof</c>, disabling tracing that has been enabled.</p> </desc> </func> <func> <name name="set_pattern" arity="3" since="OTP 27.0"/> - <fsummary>Enables memory tracing for a specific trace pattern.</fsummary> + <fsummary>Enables tracing for a specific trace pattern.</fsummary> <desc> <p>Turns tracing on for the supplied pattern. - Requires running <c>hprof</c>. Patterns are additive, following + Requires running <c>tprof</c>. Patterns are additive, following the same rules as <seemfa marker="erts:erlang#trace_pattern/3"> <c>erlang:trace_pattern/3</c></seemfa>. Returns number of functions matching the supplied pattern.</p> <code type="none"><![CDATA[ -1> hprof:set_pattern(lists, seq, '_'). +1> tprof:set_pattern(lists, seq, '_'). 2 -2> hprof:set_pattern(lists, keyfind, 3). +2> tprof:set_pattern(lists, keyfind, 3). 1 -3> hprof:get_trace_map(). +3> tprof:get_trace_map(). #{lists => [{keyfind,3},{seq,2},{seq,3}]} ]]></code> <p>If there are no functions matching the pattern, error is returned</p> <code><![CDATA[ -> hprof:set_pattern(no_module, func, '_'). +> tprof:set_pattern(no_module, func, '_'). {error,{trace_pattern,no_module,func,'_'}} ]]></code> </desc> @@ -477,15 +508,15 @@ <func> <name name="clear_pattern" arity="3" since="OTP 27.0"/> - <fsummary>Disables memory tracing for a specific trace pattern.</fsummary> + <fsummary>Disables tracing for a specific trace pattern.</fsummary> <desc> <p>Turns tracing off for the supplied pattern.</p> <code type="none"><![CDATA[ -1> hprof:set_pattern(lists, seq, '_'). +1> tprof:set_pattern(lists, seq, '_'). 2 -2> hprof:clear_pattern(lists, seq, 3). +2> tprof:clear_pattern(lists, seq, 3). 1 -3> hprof:get_trace_map(). +3> tprof:get_trace_map(). #{lists => [{seq,2}]} ]]></code> </desc> @@ -502,7 +533,7 @@ <func> <name name="enable_trace" arity="1" clause_i="1" since="OTP 27.0"/> <name name="enable_trace" arity="1" clause_i="2" since="OTP 27.0"/> - <fsummary>Enables memory tracing for the specified processes</fsummary> + <fsummary>Enables tracing for the specified processes</fsummary> <desc><p> The same as <seemfa marker="#enable_trace/2"><c>enable_trace</c> </seemfa><c>(<anno>Spec</anno>, #{set_on_spawn => true})</c>. @@ -512,11 +543,12 @@ <func> <name name="enable_trace" arity="2" clause_i="1" since="OTP 27.0"/> <name name="enable_trace" arity="2" clause_i="2" since="OTP 27.0"/> - <fsummary>Enables memory tracing for the specified processes</fsummary> + <fsummary>Enables tracing for the specified processes</fsummary> <desc><p> Similar to <seemfa marker="erts:erlang#trace/3"><c>erlang:trace/3</c></seemfa>, but supports a few more options for - heap tracing convenience. + tracing convenience. Tracing per process is not supported + by <c>call_count</c> profilers. </p> <p><c><anno>Spec</anno></c> is either a process identifier (pid) for a local process, one of the following atoms, or a @@ -544,17 +576,17 @@ </item> </taglist> <note><p> - Heap profiling server does not keep track of processes that were added + The profiling server does not keep track of processes that were added to the tracing set. It is permitted to stop the profiling server (wiping out any accumulated data), restart the server, set entirely different tracing pattern keeping the list of traced processes for future use. Use <seemfa marker="#disable_trace/2"><c>disable_trace</c>(processes)</seemfa> to clear the list of traced processes. </p></note> - <p>Specify <c><anno>Options</anno></c> to modify heap tracing behaviour:</p> + <p>Specify <c><anno>Options</anno></c> to modify tracing behaviour:</p> <taglist> <tag><c>set_on_spawn</c></tag> - <item>Automatically start heap tracing for processes spawned by the traced + <item>Automatically start tracing for processes spawned by the traced process. On by default.</item> </taglist> </desc> @@ -563,7 +595,7 @@ <func> <name name="disable_trace" arity="1" clause_i="1" since="OTP 27.0"/> <name name="disable_trace" arity="1" clause_i="2" since="OTP 27.0"/> - <fsummary>Disables memory tracing for the specified processes</fsummary> + <fsummary>Disables tracing for the specified processes</fsummary> <desc><p> The same as <seemfa marker="#disable_trace/2"><c>disable_trace</c> </seemfa><c>(<anno>Spec</anno>, #{set_on_spawn => true})</c>. @@ -573,8 +605,8 @@ <func> <name name="disable_trace" arity="2" clause_i="1" since="OTP 27.0"/> <name name="disable_trace" arity="2" clause_i="2" since="OTP 27.0"/> - <fsummary>Disables memory tracing for the specified processes</fsummary> - <desc><p>Stops accumulating heap traces for specified processes. See + <fsummary>Disables tracing for the specified processes</fsummary> + <desc><p>Stops accumulating traces for specified processes. See <seemfa marker="#enable_trace/2"><c>enable_trace/2</c></seemfa> for options description. </p> @@ -588,7 +620,7 @@ <func> <name name="pause" arity="0" since="OTP 27.0"/> - <fsummary>Pauses heap tracing.</fsummary> + <fsummary>Pauses tracing.</fsummary> <desc> <p>Pauses trace collection for all currently traced functions, keeping all traces intact. Use <seemfa marker="#continue/0"><c>continue/0</c></seemfa> to @@ -598,9 +630,9 @@ <func> <name name="continue" arity="0" since="OTP 27.0"/> - <fsummary>Resumes heap tracing.</fsummary> + <fsummary>Resumes tracing.</fsummary> <desc> - <p>Resumes previously paused heap profiling.</p> + <p>Resumes previously paused profiling.</p> </desc> </func> @@ -618,20 +650,22 @@ <name name="profile" arity="2" since="OTP 27.0"/> <name name="profile" arity="3" since="OTP 27.0"/> <name name="profile" arity="4" since="OTP 27.0"/> - <fsummary>Produces ad-hoc heap profile for the function.</fsummary> + <fsummary>Produces ad-hoc profile for the function.</fsummary> <desc> - <p>Produces ad-hoc heap profile for function <c>Fun</c> or + <p>Produces ad-hoc profile for function <c>Fun</c> or <c>Module</c>:<c>Function</c> call. By default, result is formatted to the output device, use <c>report</c> option to change this behaviour.</p> - <p>Ad-hoc profiling starts a new instance of <c>hprof</c> server, runs + <p>Ad-hoc profiling starts a new instance of <c>tprof</c> server, runs the profiling routine, extracts results and shuts the server down. If - <c>hprof</c> is already running (for server-aided profiling), default + <c>tprof</c> is already running (for server-aided profiling), default ad-hoc profiler options block this call to avoid mixing results from several independent instances. Use <c>registered => false</c> option to override this behaviour.</p> <p>Ad-hoc profiler supports following<c>Options</c>:</p> <taglist> + <tag><c>type</c></tag> + <item>The type of profiling to perform.</item> <tag><c>device</c></tag> <item>Specifies I/O devices to print the profile to. Useful to redirect text output to console or <c>standard_error</c>. @@ -641,13 +675,13 @@ By default, all functions (<c>{'_', '_', '_'}</c>) are traced. </item> <tag><c>registered</c></tag> - <item>Specifies <c>hprof</c> registered process name. Use <c>false</c> + <item>Specifies <c>tprof</c> registered process name. Use <c>false</c> to leave the process unregistered, or <c>{local, myname}</c> to register the process under a different name. </item> <tag><c>report</c></tag> <item>Controls output format. The default is <c>process</c>, printing - per-process heap profiling data sorted by percentage of the total + per-process profiling data sorted by percentage of the total allocation. Specify <c>report => return</c> to suppress printing and get the raw data for further evaluation with <seemfa marker="#inspect/3"><c>inspect/3</c></seemfa> and formatting @@ -657,10 +691,10 @@ <item>Includes extra processes in the trace list. Useful for profiling allocations for <seeerl marker="stdlib:gen_server"><c>gen_server</c></seeerl>, calls, or other allocations caused by inter-process communications. See - <seeerl marker="hprof#pg_example">example</seeerl>. + <seeerl marker="tprof#pg_example">example</seeerl>. </item> <tag><c>set_on_spawn</c></tag> - <item>Automatically start heap tracing for processes spawned by the traced + <item>Automatically start tracing for processes spawned by the traced process. On by default. </item> <tag><c>timeout</c></tag> @@ -682,7 +716,7 @@ <func> <name name="inspect" arity="1" clause_i="1" since="OTP 27.0"/> - <fsummary>Transforms raw data returned by heap profiler.</fsummary> + <fsummary>Transforms raw data returned by profiler.</fsummary> <desc><p> The same as <seemfa marker="#inspect/3"><c>inspect</c> </seemfa><c>(<anno>Profile</anno>, process, percent)</c>. Transforms @@ -694,30 +728,19 @@ <func> <name name="inspect" arity="3" clause_i="1" since="OTP 27.0"/> - <fsummary>Transforms raw data returned by heap profiler.</fsummary> + <fsummary>Transforms raw data returned by profiler.</fsummary> <desc> <p>Transforms raw data returned by tracing BIFs into a form - convenient for subsequent analysis and formatting. Returns - a map of process identifiers with corresponding profile data sorted by - the selected column.</p> - <p> - Inspected profile can be leveraged to print - <seeerl marker="hprof#inspect_example">individual process - allocations</seeerl>. - </p> - </desc> - </func> - - <func> - <name name="inspect" arity="3" clause_i="2" since="OTP 27.0"/> - <fsummary>Transforms raw data returned by heap profiler into a summary.</fsummary> - <desc> - <p>Combines raw profile from multiple processes into a single summary - sorted by the selected column.</p> + convenient for subsequent analysis and formatting.</p> + <p>When <c>process</c> is given as second argument, it returns + a map of process identifiers with corresponding profiling results + sorted by the selected column. When the second argument is + <c>total</c> or when profiling by <c>call_count</c>, the + returned map has a single <c>all</c> key with profiling results + from all processes.</p> <p> - A single profiling session may contain data from thousands or even millions - processes. This inspection mode allows to quickly glance through the allocation - summary, discarding process identifiers and keeping only totals. + Inspected profile can be leveraged to + <seeerl marker="tprof#inspect_example">print profiling results</seeerl>. </p> </desc> </func> diff --git a/lib/tools/src/Makefile b/lib/tools/src/Makefile index 67826bfd37..6f7a7914e0 100644 --- a/lib/tools/src/Makefile +++ b/lib/tools/src/Makefile @@ -38,7 +38,7 @@ RELSYSDIR = $(RELEASE_PATH)/lib/tools-$(VSN) MODULES= \ cover \ eprof \ - hprof \ + tprof \ fprof \ cprof \ lcnt \ diff --git a/lib/tools/src/hprof.erl b/lib/tools/src/tprof.erl similarity index 66% rename from lib/tools/src/hprof.erl rename to lib/tools/src/tprof.erl index 0222c5a39e..e3b3e411db 100644 --- a/lib/tools/src/hprof.erl +++ b/lib/tools/src/tprof.erl @@ -18,14 +18,16 @@ %%------------------------------------------------------------------- %% %% @author Maxim Fedorov <maximfca@gmail.com> -%% Erlang Process Heap profiler. +%% Erlang Process Tracing profiler. %% --module(hprof). +-module(tprof). %% API -export([ start/0, + start/1, start_link/0, + start_link/1, stop/0, set_pattern/3, clear_pattern/3, @@ -56,6 +58,12 @@ %% typedefs for easier digestion +%% Configures the type of profiling. +-type start_options() :: #{type => trace_type()}. + +%% Trace type +- type trace_type() :: call_count | call_time | call_memory. + %% Trace spec: module() or '_', function or '_', arity or '_' -type trace_pattern() :: {module(), Fun :: atom(), arity() | '_'}. @@ -64,17 +72,17 @@ %% Single trace_info call with associated module/function/arity -type trace_info() :: {module(), Fun :: atom(), Arity :: non_neg_integer(), - [{pid(), Count :: pos_integer(), Words :: pos_integer()}]}. + [{pid(), Count :: pos_integer(), Measurement :: pos_integer()}]}. %% Combined report for a single function (one or all processes). -type profile_line() :: {module(), Function :: {atom(), arity()}, - Count :: pos_integer(), Words :: pos_integer(), WordsPerCall :: non_neg_integer(), Percent :: float()}. + Count :: pos_integer(), Measurement :: pos_integer(), MeasurementPerCall :: non_neg_integer(), Percent :: float()}. %% Single profiling attempt result. --type profile_result() :: {TotalWords :: non_neg_integer(), [profile_line()]}. +-type profile_result() :: {trace_type(), TotalMeasurement :: non_neg_integer(), [profile_line()]}. %% Convenience type used to sort the profiling results. --type column() :: module | function | calls | words | words_per_call | percent. +-type column() :: module | function | calls | measurement | measurement_per_call | percent. %% Sort by -type sort_by() :: column() | {column(), ascending} | {column(), descending}. @@ -91,6 +99,7 @@ new_processes. -type profile_options() :: #{ + type => trace_type(), %% the type of profiling timeout => timeout(), %% stop profiling after the timeout pattern => trace_pattern() | [trace_pattern()], %% list of patterns to trace set_on_spawn => boolean(), %% trace spawned processes or not (true by default) @@ -104,12 +113,22 @@ %% Server-aided API -spec start() -> {'ok', Pid} | {'error', Reason} when Pid :: pid(), Reason :: {'already_started', Pid}. start() -> - gen_server:start({local, ?MODULE}, ?MODULE, [], []). + start(#{}). + +-spec start(start_options()) -> {'ok', Pid} | {'error', Reason} + when Pid :: pid(), Reason :: {'already_started', Pid}. +start(Config) when is_map(Config) -> + gen_server:start({local, ?MODULE}, ?MODULE, Config, []). %% @doc Starts the process and links it to the caller. -spec start_link() -> {'ok', Pid} | {'error', Reason} when Pid :: pid(), Reason :: {'already_started', Pid}. start_link() -> - gen_server:start_link({local, ?MODULE}, ?MODULE, [], []). + start_link(#{}). + +-spec start_link(start_options()) -> {'ok', Pid} | {'error', Reason} + when Pid :: pid(), Reason :: {'already_started', Pid}. +start_link(Config) when is_map(Config) -> + gen_server:start_link({local, ?MODULE}, ?MODULE, Config, []). -spec stop() -> ok. stop() -> @@ -130,7 +149,7 @@ get_trace_map() -> gen_server:call(?MODULE, get_trace_map). %% @doc Returns statistics for current trace map. --spec collect() -> [trace_info()]. +-spec collect() -> {trace_type(), [trace_info()]}. collect() -> gen_server:call(?MODULE, collect, infinity). @@ -213,29 +232,30 @@ restart() -> %%-------------------------------------------------------------------- %% Common API -%% @doc Transforms raw collected data into shape suitable for analysis and printing. --spec inspect([trace_info()]) -> #{pid() => profile_result()}. +%% @doc Shortcut to transform raw collected data by process, sorted by percent. +-spec inspect({trace_type(), [trace_info()]}) -> #{pid() | all => profile_result()}. inspect(Profile) -> inspect(Profile, process, percent). --spec inspect([trace_info()], Report :: process, sort_by()) -> #{pid() => profile_result()}; - ([trace_info()], Report :: total, sort_by()) -> profile_result(). -inspect(Profile, process, SortBy) -> +%% @doc Transforms raw collected data into shape suitable for analysis and printing. +-spec inspect({trace_type(), [trace_info()]}, process | total, sort_by()) -> + #{pid() | all => profile_result()}. +inspect({Type, Profile}, process, SortBy) -> maps:map( fun (_Pid, {Total, Stats}) -> - {Total, inspect_sort(Stats, SortBy)} + {Type, Total, inspect_sort(Stats, SortBy)} end, inspect_processes(Profile, #{})); -inspect(Profile, total, SortBy) -> - GrandTotal = lists:sum([Words || {_M, _F, _A, Mem} <- Profile, {_P, _C, Words} <- Mem]), - TotalStats = [inspect_total(M, F, A, GrandTotal, Mem) || {M, F, A, Mem} <- Profile], - {GrandTotal, inspect_sort(TotalStats, SortBy)}. +inspect({Type, Profile}, total, SortBy) -> + GrandTotal = lists:sum([Mem || {_M, _F, _A, Mems} <- Profile, {_P, _C, Mem} <- Mems]), + TotalStats = [inspect_total(M, F, A, GrandTotal, Mems) || {M, F, A, Mems} <- Profile], + #{all => {Type, GrandTotal, inspect_sort(TotalStats, SortBy)}}. %% @doc Formats inspect()-ed totals and per-function data --spec format(profile_result() | #{pid => profile_result()}) -> ok. +-spec format(#{pid() | all => profile_result()}) -> ok. format(Inspected) -> format_impl([], Inspected). --spec format(io:device(), profile_result() | #{pid => profile_result()}) -> ok. +-spec format(io:device(), #{pid() | all => profile_result()}) -> ok. format(IoDevice, Inspected) -> format_impl(IoDevice, Inspected). @@ -261,7 +281,8 @@ profile(Module, Function, Args, Options) when is_atom(Module), is_atom(Function) %%-------------------------------------------------------------------- %% gen_server implementation --record(hprof_state, { +-record(tprof_state, { + type = call_count :: trace_type(), trace_map = #{} :: trace_map(), paused = false :: boolean(), ad_hoc = undefined :: undefined | @@ -269,41 +290,42 @@ profile(Module, Function, Args, Options) when is_atom(Module), is_atom(Function) RootSet :: rootset(), ReplyTo :: gen_server:from()} }). --type state() :: #hprof_state{}. +-type state() :: #tprof_state{}. --spec init([]) -> {ok, state()}. -init([]) -> +-spec init(start_options()) -> {ok, state()}. +init(Config) -> + Type = maps:get(type, Config, call_count), false = erlang:process_flag(trap_exit, true), %% need this for reliable terminate/2 call - {ok, #hprof_state{}}. + {ok, #tprof_state{type=Type}}. -spec handle_call(term(), gen_server:from(), state()) -> {reply | noreply, term(), state()}. -handle_call({set_pattern, M, F, A}, _From, #hprof_state{trace_map = Map} = State) -> - {Reply, NewMap} = enable_pattern(M, F, A, Map), - {reply, Reply, State#hprof_state{trace_map = NewMap}}; -handle_call({clear_pattern, M, F, A}, _From, #hprof_state{trace_map = Map} = State) -> - {Ret, NewMap} = disable_pattern(M, F, A, Map), - {reply, Ret, State#hprof_state{trace_map = NewMap}}; -handle_call(get_trace_map, _From, #hprof_state{trace_map = Map} = State) -> +handle_call({set_pattern, M, F, A}, _From, #tprof_state{trace_map = Map, type = Type} = State) -> + {Reply, NewMap} = enable_pattern(M, F, A, Map, Type), + {reply, Reply, State#tprof_state{trace_map = NewMap}}; +handle_call({clear_pattern, M, F, A}, _From, #tprof_state{trace_map = Map, type = Type} = State) -> + {Ret, NewMap} = disable_pattern(M, F, A, Map, Type), + {reply, Ret, State#tprof_state{trace_map = NewMap}}; +handle_call(get_trace_map, _From, #tprof_state{trace_map = Map} = State) -> {reply, Map, State}; -handle_call(pause, _From, #hprof_state{paused = true} = State) -> +handle_call(pause, _From, #tprof_state{paused = true} = State) -> {reply, not_running, State}; -handle_call(pause, _From, #hprof_state{trace_map = Map, paused = false} = State) -> - foreach(Map, pause), - {reply, ok, State#hprof_state{paused = true}}; -handle_call(continue, _From, #hprof_state{paused = false} = State) -> +handle_call(pause, _From, #tprof_state{trace_map = Map, paused = false, type = Type} = State) -> + foreach(Map, pause, Type), + {reply, ok, State#tprof_state{paused = true}}; +handle_call(continue, _From, #tprof_state{paused = false} = State) -> {reply, running, State}; -handle_call(continue, _From, #hprof_state{trace_map = Map} = State) -> - foreach(Map, true), - {reply, ok, State#hprof_state{paused = false}}; -handle_call(restart, _From, #hprof_state{trace_map = Map} = State) -> - foreach(Map, restart), - {reply, ok, State#hprof_state{paused = false}}; -handle_call(collect, _From, #hprof_state{trace_map = Map} = State) -> - {reply, collect(Map), State}; -handle_call({profile, What, Options}, From, #hprof_state{ad_hoc = undefined, trace_map = Map} = State) -> +handle_call(continue, _From, #tprof_state{trace_map = Map, type = Type} = State) -> + foreach(Map, true, Type), + {reply, ok, State#tprof_state{paused = false}}; +handle_call(restart, _From, #tprof_state{trace_map = Map, type = Type} = State) -> + foreach(Map, restart, Type), + {reply, ok, State#tprof_state{paused = false}}; +handle_call(collect, _From, #tprof_state{trace_map = Map, type = Type} = State) -> + {reply, collect(Map, Type), State}; +handle_call({profile, What, Options}, From, #tprof_state{ad_hoc = undefined, trace_map = Map, type = Type} = State) -> %% ad-hoc profile routed via gen_server to handle 'EXIT' signal - {Pid, Timer, Patterns, RootSet, NewMap} = ad_hoc_run(What, Options, Map), - {noreply, State#hprof_state{ad_hoc = {Pid, Timer, Patterns, RootSet, From}, trace_map = NewMap}}; + {Pid, Timer, Patterns, RootSet, NewMap} = ad_hoc_run(What, Options, Map, Type), + {noreply, State#tprof_state{ad_hoc = {Pid, Timer, Patterns, RootSet, From}, trace_map = NewMap}}; handle_call({profile, _What, _Options}, _From, State) -> {reply, {error, running}, State}. @@ -312,24 +334,24 @@ handle_cast(_Req, _State) -> erlang:error(notsup). -spec handle_info(term(), state()) -> {noreply, state()}. -handle_info({'EXIT', Pid, Reason}, #hprof_state{ad_hoc = {Pid, Timer, Patterns, RootSet, From}, - trace_map = Map} = State) -> +handle_info({'EXIT', Pid, Reason}, #tprof_state{ad_hoc = {Pid, Timer, Patterns, RootSet, From}, + trace_map = Map, type = Type} = State) -> _ = disable_trace(RootSet), - Profile = collect(Map), + Profile = collect(Map, Type), gen:reply(From, {Reason, Profile}), Timer =/= false andalso erlang:cancel_timer(Timer), - {noreply, State#hprof_state{ad_hoc = undefined, trace_map = disable_patterns(Patterns, Map)}}; + {noreply, State#tprof_state{ad_hoc = undefined, trace_map = disable_patterns(Patterns, Map, Type)}}; -handle_info({cancel, Pid}, #hprof_state{ad_hoc = {Pid, _Timer, Patterns, RootSet, From}, - trace_map = Map} = State) -> +handle_info({cancel, Pid}, #tprof_state{ad_hoc = {Pid, _Timer, Patterns, RootSet, From}, + trace_map = Map, type = Type} = State) -> _ = disable_trace(RootSet), - Profile = collect(Map), + Profile = collect(Map, Type), gen:reply(From, {{'EXIT', timeout}, Profile}), - {noreply, State#hprof_state{ad_hoc = undefined, trace_map = disable_patterns(Patterns, Map)}}. + {noreply, State#tprof_state{ad_hoc = undefined, trace_map = disable_patterns(Patterns, Map, Type)}}. -spec terminate(term(), state()) -> ok. -terminate(_Reason, #hprof_state{trace_map = Map}) -> - clear_pattern(Map), +terminate(_Reason, #tprof_state{trace_map = Map, type = Type}) -> + clear_pattern(Map, Type), ok. %%-------------------------------------------------------------------- @@ -338,10 +360,10 @@ terminate(_Reason, #hprof_state{trace_map = Map}) -> -include_lib("kernel/include/logger.hrl"). %% Add the trace of the specified module to the accumulator -collect_trace(Mod, FunList, Acc) -> +collect_trace(Mod, FunList, Acc, Type) -> {Fail, Ret} = lists:foldl( fun ({Fun, Arity}, {Fail, Prev}) -> - case combine_trace(erlang:trace_info({Mod, Fun, Arity}, call_memory)) of + case combine_trace(erlang:trace_info({Mod, Fun, Arity}, Type)) of skip -> {Fail, Prev}; fail -> @@ -353,20 +375,26 @@ collect_trace(Mod, FunList, Acc) -> %% module may have been hot-code reloaded, or tracing was broken by something else Fail andalso begin ?LOG_WARNING( - "hprof encountered an error tracing module ~s, was it reloaded or untraced?", + "tprof encountered an error tracing module ~s, was it reloaded or untraced?", [Mod]) end, Ret. -combine_trace({call_memory, []}) -> - skip; %% It is possible that due to hot code reload event %% some function is no longer traced, while it was supposed to. %% Reinstating tracing automatically is wrong thing to do, because %% statistics won't be correct anyway. Hence the warning in the user %% guide, guarding against hot code reload while tracing. -combine_trace({call_memory, false}) -> - fail; +combine_trace({_, false}) -> fail; +combine_trace({call_count, 0}) -> skip; +combine_trace({call_count, Num}) -> [{all, Num, Num}]; +combine_trace({call_time, Times}) -> + case [{Pid, Calls, S * 1000000 + Us} || {Pid, Calls, S, Us} <- Times] of + [] -> + skip; + NonZero -> + NonZero + end; combine_trace({call_memory, Mem}) -> case [{Pid, Calls, Words} || {Pid, Calls, Words} <- Mem, Words > 0] of [] -> @@ -376,35 +404,38 @@ combine_trace({call_memory, Mem}) -> end. %% Inspection: iterate over collected traces, return map of -%% #{Pid => [{M, {F, A}, Calls, TotalWords, WordsPerCall, Percentage}], unsorted. +%% #{Pid => [{M, {F, A}, Calls, Measurement, PerCall, Percentage}], unsorted. inspect_processes([], Acc) -> maps:map( fun (_Pid, {Total, Lines}) -> - {Total, [{M, {F, A}, Calls, Words, PerCall, Words * 100 / Total} - || {M, F, A, Calls, Words, PerCall} <- Lines]} + {Total, [{M, {F, A}, Calls, Measurement, PerCall, divide(Measurement * 100, Total)} + || {M, F, A, Calls, Measurement, PerCall} <- Lines]} end, Acc); inspect_processes([{_M, _F, _A, []} | Tail], Acc) -> inspect_processes(Tail, Acc); -inspect_processes([{M, F, A, [{Pid, Calls, Words} | MemTail]} | Tail], Acc) -> - ProfLine = {M, F, A, Calls, Words, Words div Calls}, - inspect_processes([{M, F, A, MemTail} | Tail], - maps:update_with(Pid, fun ({Grand, L}) -> {Grand + Words, [ProfLine | L]} end, {Words, [ProfLine]}, Acc)). +inspect_processes([{M, F, A, [{Pid, Calls, Mem} | TripletTail]} | Tail], Acc) -> + ProfLine = {M, F, A, Calls, Mem, divide(Mem, Calls)}, + inspect_processes([{M, F, A, TripletTail} | Tail], + maps:update_with(Pid, fun ({Grand, L}) -> {Grand + Mem, [ProfLine | L]} end, {Mem, [ProfLine]}, Acc)). %% Inspection: remove Pid information from the Profile, return list of -%% [{M, F, A, TotalCalls, TotalWords, WordsPerCall, Percentage}] -inspect_total(M, F, A, GrandTotal, Mem) -> - {TC, TW} = lists:foldl( - fun ({_Pid, Calls, Words}, {TotalCalls, TotalWords}) -> - {TotalCalls + Calls, TotalWords + Words} - end, {0, 0}, Mem), - {M, {F, A}, TC, TW, TW div TC, TW * 100 / GrandTotal}. +%% [{M, F, A, TotalCalls, Measurement, PerCall, Percentage}] +inspect_total(M, F, A, GrandTotal, Mems) -> + {TC, TM} = lists:foldl( + fun ({_Pid, Calls, Mem}, {TotalCalls, TotalMem}) -> + {TotalCalls + Calls, TotalMem + Mem} + end, {0, 0}, Mems), + {M, {F, A}, TC, TM, divide(TM, TC), divide(TM * 100, GrandTotal)}. + +divide(_,0) -> 0.0; +divide(T,N) -> T/N. %% Returns "sort by" column index column(module) -> {1, ascending}; column(function) -> {2, ascending}; column(calls) -> {3, ascending}; -column(words) -> {4, ascending}; -column(words_per_call) -> {5, ascending}; +column(measurement) -> {4, ascending}; +column(measurement_per_call) -> {5, ascending}; column(percent) -> {6, ascending}. %% Sorts by column name, ascending/descending @@ -423,38 +454,67 @@ inspect_sort(Profile, Column) when is_atom(Column) -> %% Formats the inspected profile to the Device, which could be [] meaning %% default output. format_impl(Device, Empty) when Empty =:= #{} -> - format_out(Device, "Memory trace is empty~n", []); + format_out(Device, "Trace is empty~n", []); +format_impl(Device, #{all := {Type, Total, Inspected}}) -> + format_each(Device, Type, Total, Inspected); format_impl(Device, Inspected) when is_map(Inspected) -> %% grab the total-total words - GrandTotal = maps:fold(fun (_Pid, {Total, _Profile}, Acc) -> Acc + Total end, 0, Inspected), + GrandTotal = maps:fold(fun (_Pid, {_Type, Total, _Profile}, Acc) -> Acc + Total end, 0, Inspected), %% per-process printout maps:foreach( - fun(Pid, {Total, _} = Profile) -> - format_out(Device, "~n****** Process ~w -- ~.2f % of total allocations *** ~n", - [Pid, 100 * Total / GrandTotal]), - format_impl(Device, Profile) - end, Inspected); -format_impl(Device, {Total, Inspected}) when is_list(Inspected) -> + fun(Pid, {Type, Total, Each}) -> + format_out(Device, "~n****** Process ~w -- ~.2f% of total *** ~n", + [Pid, divide(100 * Total, GrandTotal)]), + format_each(Device, Type, Total, Each) + end, Inspected). + +format_each(Device, call_count, _Total, Inspected) -> + %% viewport size + %% Viewport = case io:columns() of {ok, C} -> C; _ -> 80 end, + %% layout: module and fun/arity columns are resizable, the rest are not + %% convert all lines to strings + {Widths, Lines} = lists:foldl( + fun ({Mod, {F, A}, Calls, _Value, _VPC, Percent}, {Widths, Ln}) -> + Line = [lists:flatten(io_lib:format("~tw:~tw/~w", [Mod, F, A])), + integer_to_list(Calls), float_to_list(Percent, [{decimals, 2}])], + NewWidths = [erlang:max(Old, New) || {Old, New} <- lists:zip([string:length(L) || L <- Line], Widths)], + {NewWidths, [Line | Ln]} + end, {[0, 5, 5], []}, Inspected), + %% figure our max column widths according to viewport (cut off module/funArity) + FilteredWidths = Widths, + %% figure out formatting line + Fmt = lists:flatten(io_lib:format("~~.~wts ~~~ws [~~~ws]~~n", FilteredWidths)), + %% print using this format + format_out(Device, Fmt, ["FUNCTION", "CALLS", "%"]), + [format_out(Device, Fmt, Line) || Line <- lists:reverse(Lines)], + format_out(Device, Fmt, [" ", " ", "100.0"]); +format_each(Device, call_time, Total, Inspected) -> + format_labelled(Device, "TIME (μs)", Total, Inspected); +format_each(Device, call_memory, Total, Inspected) -> + format_labelled(Device, "WORDS", Total, Inspected). + +format_labelled(Device, Label, Total, Inspected) -> %% viewport size %% Viewport = case io:columns() of {ok, C} -> C; _ -> 80 end, %% layout: module and fun/arity columns are resizable, the rest are not %% convert all lines to strings {Widths, Lines} = lists:foldl( - fun ({Mod, {F, A}, Calls, Words, WPC, Percent}, {Widths, Ln}) -> - Line = [atom_to_list(Mod), lists:flatten(io_lib:format("~tw/~w", [F, A])), - integer_to_list(Calls), integer_to_list(Words), integer_to_list(WPC), + fun ({Mod, {F, A}, Calls, Value, VPC, Percent}, {Widths, Ln}) -> + Line = [lists:flatten(io_lib:format("~tw:~tw/~w", [Mod, F, A])), + integer_to_list(Calls), integer_to_list(Value), + float_to_list(VPC, [{decimals, 2}]), float_to_list(Percent, [{decimals, 2}])], NewWidths = [erlang:max(Old, New) || {Old, New} <- lists:zip([string:length(L) || L <- Line], Widths)], {NewWidths, [Line | Ln]} - end, {[0, 0, 5, 5, 8, 5], []}, Inspected), + end, {[0, 5, length(Label), 8, 5], []}, Inspected), %% figure our max column widths according to viewport (cut off module/funArity) FilteredWidths = Widths, %% figure out formatting line - Fmt = lists:flatten(io_lib:format("~~.~ws ~~.~wts ~~~ws ~~~ws ~~~ws [~~~ws]~~n", FilteredWidths)), + Fmt = lists:flatten(io_lib:format("~~.~wts ~~~ws ~~~wts ~~~ws [~~~ws]~~n", FilteredWidths)), %% print using this format - format_out(Device, Fmt, ["MODULE", "FUN/ARITY", "CALLS", "WORDS", "PER CALL", "%"]), + format_out(Device, Fmt, ["FUNCTION", "CALLS", Label, "PER CALL", "%"]), [format_out(Device, Fmt, Line) || Line <- lists:reverse(Lines)], - format_out(Device, Fmt, [" ", " ", " ", integer_to_list(Total), " ", "100.0"]). + format_out(Device, Fmt, [" ", " ", integer_to_list(Total), " ", "100.0"]). %% format implementation that uses [] as a way to tell "default output" format_out([], Fmt, Args) -> @@ -463,24 +523,24 @@ format_out(Device, Fmt, Args) -> io:format(Device, Fmt, Args). %% pattern collapse code -enable_pattern('_', '_', '_', _Acc) -> +enable_pattern('_', '_', '_', _Acc, Type) -> %% need to re-trace everything, probably some new modules were loaded %% discard any existing trace pattern lists:foldl( fun({Mod, _}, {Total, Acc}) -> - Plus = erlang:trace_pattern({Mod, '_', '_'}, true, [call_memory]), + Plus = erlang:trace_pattern({Mod, '_', '_'}, true, [Type]), {Total + Plus, Acc#{Mod => Mod:module_info(functions)}} end, {0, #{}}, code:all_loaded()); -enable_pattern(Mod, '_', '_', Acc) -> +enable_pattern(Mod, '_', '_', Acc, Type) -> %% code may have been hot-loaded, redo the trace - case erlang:trace_pattern({Mod, '_', '_'}, true, [call_memory]) of + case erlang:trace_pattern({Mod, '_', '_'}, true, [Type]) of 0 -> {{error, {trace_pattern, Mod, '_', '_'}}, Acc}; Traced -> {Traced, Acc#{Mod => Mod:module_info(functions)}} end; -enable_pattern(Mod, Fun, '_', Acc) -> - case erlang:trace_pattern({Mod, Fun, '_'}, true, [call_memory]) of +enable_pattern(Mod, Fun, '_', Acc, Type) -> + case erlang:trace_pattern({Mod, Fun, '_'}, true, [Type]) of 0 -> {{error, {trace_pattern, Mod, Fun, '_'}}, Acc}; Traced -> @@ -491,8 +551,8 @@ enable_pattern(Mod, Fun, '_', Acc) -> end, Added, Acc), {Traced, NewMap} end; -enable_pattern(Mod, Fun, Arity, Acc) -> - case erlang:trace_pattern({Mod, Fun, Arity}, true, [call_memory]) of +enable_pattern(Mod, Fun, Arity, Acc, Type) -> + case erlang:trace_pattern({Mod, Fun, Arity}, true, [Type]) of 0 -> {{error, {trace_pattern, Mod, Fun, Arity}}, Acc}; 1 -> @@ -501,29 +561,33 @@ enable_pattern(Mod, Fun, Arity, Acc) -> end. %% pattern collapse code for un-tracing -disable_pattern('_', '_', '_', _Acc) -> - Traced = erlang:trace_pattern({'_', '_', '_'}, false, [call_memory]), +disable_pattern('_', '_', '_', _Acc, Type) -> + Traced = erlang:trace_pattern({'_', '_', '_'}, false, [Type]), {Traced, #{}}; -disable_pattern(Mod, '_', '_', Acc) when is_map_key(Mod, Acc) -> - Traced = erlang:trace_pattern({Mod, '_', '_'}, false, [call_memory]), +disable_pattern(Mod, '_', '_', Acc, Type) when is_map_key(Mod, Acc) -> + Traced = erlang:trace_pattern({Mod, '_', '_'}, false, [Type]), {Traced, maps:remove(Mod, Acc)}; -disable_pattern(Mod, Fun, '_', Acc) when is_map_key(Mod, Acc) -> - Traced = erlang:trace_pattern({Mod, Fun, '_'}, false, [call_memory]), +disable_pattern(Mod, Fun, '_', Acc, Type) when is_map_key(Mod, Acc) -> + Traced = erlang:trace_pattern({Mod, Fun, '_'}, false, [Type]), {Traced, maps:update_with(Mod, fun (FAs) -> [{F, A} || {F, A} <- FAs, F =/= Fun] end, Acc)}; -disable_pattern(Mod, Fun, Arity, Acc) when is_map_key(Mod, Acc) -> - Traced = erlang:trace_pattern({Mod, Fun, Arity}, false, [call_memory]), +disable_pattern(Mod, Fun, Arity, Acc, Type) when is_map_key(Mod, Acc) -> + Traced = erlang:trace_pattern({Mod, Fun, Arity}, false, [Type]), {Traced, maps:update_with(Mod, fun (FAs) -> FAs -- [{Fun, Arity}] end, Acc)}; -disable_pattern(Mod, Fun, Arity, Acc) -> +disable_pattern(Mod, Fun, Arity, Acc, _Type) -> {{error, {not_traced, Mod, Fun, Arity}}, Acc}. -disable_patterns(Patterns, Map) -> - lists:foldl(fun ({M, F, A}, Acc) -> {_, New} = disable_pattern(M, F, A, Acc), New end, Map, Patterns). +disable_patterns(Patterns, Map, Type) -> + lists:foldl( + fun ({M, F, A}, Acc) -> {_, New} = disable_pattern(M, F, A, Acc, Type), New end, + Map, + Patterns + ). %% ad-hoc profiler implementation do_profile(What, Options) -> - %% start a new hprof server, potentially registered to a new name - Pid = start_result(start_internal(maps:get(registered, Options, {local, ?MODULE}))), + %% start a new tprof server, potentially registered to a new name + Pid = start_result(start_internal(Options)), try {Ret, Profile} = gen_server:call(Pid, {profile, What, Options}, infinity), return_profile(maps:get(report, Options, process), Profile, Ret, @@ -532,10 +596,11 @@ do_profile(What, Options) -> gen_server:stop(Pid) end. -start_internal(false) -> - gen_server:start_link(?MODULE, [], []); -start_internal({local, Name}) -> - gen_server:start_link({local, Name}, ?MODULE, [], []). +start_internal(Options) -> + case maps:get(registered, Options, {local, ?MODULE}) of + false -> gen_server:start_link(?MODULE, Options, []); + {local, Name} -> gen_server:start_link({local, Name}, ?MODULE, Options, []) + end. start_result({ok, Pid}) -> Pid; start_result({error, Reason}) -> erlang:error(Reason). @@ -550,11 +615,11 @@ return_profile({Agg, Sort}, Profile, _Ret, Device) -> format_impl(Device, inspect(Profile, Agg, Sort)). %% @doc clears tracing for the entire trace map passed --spec clear_pattern(trace_map()) -> ok. -clear_pattern(Existing) -> +-spec clear_pattern(trace_map(), trace_type()) -> ok. +clear_pattern(Existing, Type) -> maps:foreach( fun (Mod, FunArity) -> - [erlang:trace_pattern({Mod, F, A}, false, [call_memory]) || {F, A} <- FunArity] + [erlang:trace_pattern({Mod, F, A}, false, [Type]) || {F, A} <- FunArity] end, Existing). trace_options(#{set_on_spawn := false}) -> @@ -631,22 +696,22 @@ toggle_trace([Name | Tail], On, Flags, Success, Failure) when is_atom(Name) -> %% @doc Collects memory tracing data (usable for inspect()) for %% all traced functions. --spec collect(trace_map()) -> [trace_info()]. -collect(Pattern) -> - maps:fold(fun collect_trace/3, [], Pattern). +-spec collect(trace_map(), trace_type()) -> {trace_type(), [trace_info()]}. +collect(Pattern, Type) -> + {Type, maps:fold(fun(K, V, Acc) -> collect_trace(K, V, Acc, Type) end, [], Pattern)}. -foreach(Map, Action) -> +foreach(Map, Action, Type) -> maps:foreach( fun (Mod, Funs) -> - [erlang:trace_pattern({Mod, F, A}, Action, [call_memory]) || {F, A} <- Funs] + [erlang:trace_pattern({Mod, F, A}, Action, [Type]) || {F, A} <- Funs] end, Map). -ad_hoc_run(What, Options, Map) -> +ad_hoc_run(What, Options, Map, Type) -> %% add missing patterns Patterns = make_list(maps:get(pattern, Options, {'_', '_', '_'})), NewMap = lists:foldl( fun({M, F, A}, Acc) -> - {_, NewMap} = enable_pattern(M, F, A, Acc), + {_, NewMap} = enable_pattern(M, F, A, Acc, Type), NewMap end, Map, Patterns), %% check whether spawned processes are also traced diff --git a/lib/tools/test/Makefile b/lib/tools/test/Makefile index 0b233211b0..ce86a58529 100644 --- a/lib/tools/test/Makefile +++ b/lib/tools/test/Makefile @@ -23,7 +23,7 @@ include $(ERL_TOP)/make/$(TARGET)/otp.mk MODULES = \ cover_SUITE \ eprof_SUITE \ - hprof_SUITE \ + tprof_SUITE \ emacs_SUITE \ fprof_SUITE \ cprof_SUITE \ diff --git a/lib/tools/test/hprof_SUITE.erl b/lib/tools/test/tprof_SUITE.erl similarity index 52% rename from lib/tools/test/hprof_SUITE.erl rename to lib/tools/test/tprof_SUITE.erl index 76db59b894..dc12e41cf8 100644 --- a/lib/tools/test/hprof_SUITE.erl +++ b/lib/tools/test/tprof_SUITE.erl @@ -17,7 +17,7 @@ %%------------------------------------------------------------------- %% @author Maxim Fedorov <maximfca@gmail.com> %% Basic heap profiler tests. --module(hprof_SUITE). +-module(tprof_SUITE). -author("maximfca@gmail.com"). %% Test server callbacks @@ -25,7 +25,9 @@ %% Test cases exports -export([ - ad_hoc/0, ad_hoc/1, + call_count_ad_hoc/0, call_count_ad_hoc/1, + call_time_ad_hoc/0, call_time_ad_hoc/1, + call_memory_ad_hoc/0, call_memory_ad_hoc/1, sort/0, sort/1, rootset/0, rootset/1, set_on_spawn/0, set_on_spawn/1, seq/1, @@ -46,22 +48,33 @@ suite() -> [{timetrap, {seconds, 60}}]. all() -> - [ad_hoc, sort, rootset, set_on_spawn, live_trace, patterns, - processes, server, hierarchy, code_reload]. + [call_count_ad_hoc, call_time_ad_hoc, call_memory_ad_hoc, + sort, rootset, set_on_spawn, live_trace, patterns, + processes, server, hierarchy, code_reload]. %%-------------------------------------------------------------------- %% TEST CASES -ad_hoc() -> - [{doc, "Ad-hoc examples from documentation"}]. +call_count_ad_hoc() -> + [{doc, "Ad-hoc examples for call_count measurement"}]. -ad_hoc(Config) when is_list(Config) -> +call_count_ad_hoc(Config) when is_list(Config) -> ct:capture_start(), - ok = hprof:profile(lists, seq, [1, 16]), + ok = tprof:profile(lists, seq, [1, 16]), ct:capture_stop(), Output = string:lexemes(lists:flatten(ct:capture_get()), "\n"), - %% expect third line to contain lists:seq_loop: "lists seq_loop/3 5 32 6 [100.00]", - ?assertMatch(["lists", "seq_loop/3", "5", "32" | _], string:lexemes(lists:nth(3, Output), " ")), + %% expect one line to contain lists:seq_loop: "lists:seq_loop/3 5 [ ...]", + true = + lists:any( + fun + ("lists:seq_loop/3" ++ Rest) -> + [_, "[", _] = string:lexemes(Rest, " "), + true; + (_) -> + false + end, + Output + ), %% spawn examples SpawnFun = fun () -> @@ -69,13 +82,75 @@ ad_hoc(Config) when is_list(Config) -> receive {'DOWN', MRef, process, Pid, normal} -> done end end, %% trace subset examples - {done, Profile1} = hprof:profile(SpawnFun, #{pattern => [{lists, seq_loop, '_'}], report => return}), - ?assertMatch([{lists, seq_loop, 3, [{_, 9, 64}]}], Profile1), + {done, Profile1} = tprof:profile(SpawnFun, #{pattern => [{lists, seq_loop, '_'}], report => return, type => call_count}), + ?assertMatch({call_count, [{lists, seq_loop, 3, [{all, _, _}]}]}, Profile1), %% timer - {{'EXIT', timeout}, Profile2} = hprof:profile( + {{'EXIT', timeout}, Profile2} = tprof:profile( fun () -> Delay = hd(lists:seq(5001, 5032)), timer:sleep(Delay) end, - #{timeout => 1000, report => return}), - ?assertMatch([{lists, seq_loop, 3, [{_, 9, 64}]}], Profile2). + #{timeout => 1000, report => return, type => call_count, + pattern => [{lists, seq_loop, '_'}]}), + ?assertMatch({call_count, [{lists, seq_loop, 3, [{all, _, _}]}]}, Profile2). + +call_time_ad_hoc() -> + [{doc, "Ad-hoc examples for call_time measurement"}]. + +call_time_ad_hoc(Config) when is_list(Config) -> + ct:capture_start(), + ok = tprof:profile(lists, seq, [1, 16], #{type => call_time}), + ct:capture_stop(), + Output = string:lexemes(lists:flatten(ct:capture_get()), "\n"), + %% expect one line to contain lists:seq_loop: "lists:seq_loop/3 5 ... ... [...]", + true = + lists:any( + fun + ("lists:seq_loop/3" ++ Rest) -> + ["5", _, _, "[" ++ _ | _] = string:lexemes(Rest, " "), + true; + (_) -> + false + end, + Output + ), + %% spawn examples + SpawnFun = + fun () -> + {Pid, MRef} = spawn_monitor(fun () -> lists:seq(1, 32) end), + receive {'DOWN', MRef, process, Pid, normal} -> done end + end, + %% trace subset examples + {done, Profile1} = tprof:profile(SpawnFun, #{pattern => [{lists, seq_loop, '_'}], report => return, type => call_time}), + ?assertMatch({call_time, [{lists, seq_loop, 3, [{_, 9, _}]}]}, Profile1), + %% timer + {{'EXIT', timeout}, Profile2} = tprof:profile( + fun () -> Delay = hd(lists:seq(5001, 5032)), timer:sleep(Delay) end, + #{timeout => 1000, report => return, type => call_time, + pattern => [{lists, seq_loop, '_'}]}), + ?assertMatch({call_time, [{lists, seq_loop, 3, [{_, 9, _}]}]}, Profile2). + +call_memory_ad_hoc() -> + [{doc, "Ad-hoc examples for call_memory measurement"}]. + +call_memory_ad_hoc(Config) when is_list(Config) -> + ct:capture_start(), + ok = tprof:profile(lists, seq, [1, 16], #{type => call_memory}), + ct:capture_stop(), + Output = string:lexemes(lists:flatten(ct:capture_get()), "\n"), + %% expect third line to contain lists:seq_loop: "lists:seq_loop/3 5 32 6.40 [...]", + ?assertMatch(["lists:seq_loop/3", "5", "32", _, "[" ++ _ | _], string:lexemes(lists:nth(3, Output), " ")), + %% spawn examples + SpawnFun = + fun () -> + {Pid, MRef} = spawn_monitor(fun () -> lists:seq(1, 32) end), + receive {'DOWN', MRef, process, Pid, normal} -> done end + end, + %% trace subset examples + {done, Profile1} = tprof:profile(SpawnFun, #{pattern => [{lists, seq_loop, '_'}], report => return, type => call_memory}), + ?assertMatch({call_memory, [{lists, seq_loop, 3, [{_, 9, 64}]}]}, Profile1), + %% timer + {{'EXIT', timeout}, Profile2} = tprof:profile( + fun () -> Delay = hd(lists:seq(5001, 5032)), timer:sleep(Delay) end, + #{timeout => 1000, report => return, type => call_memory}), + ?assertMatch({call_memory, [{lists, seq_loop, 3, [{_, 9, 64}]}]}, Profile2). sort() -> [{doc, "Tests sorting methods work"}]. @@ -83,14 +158,14 @@ sort() -> sort(Config) when is_list(Config) -> %% sort examples ct:capture_start(), - ok = hprof:profile( + ok = tprof:profile( fun () -> Group = lists:seq(100, 120), rand:uniform(hd(Group)) - end, #{report => {process, {words_per_call, descending}}}), + end, #{report => {process, {measurement_per_call, descending}}, type => call_memory}), ct:capture_stop(), Out = string:lexemes(lists:flatten(ct:capture_get()), "\n"), - %% words per call is 5th column + %% measurement per call is 5th column Col = 5, Column5 = [string:to_integer(lists:nth(Col, Lexemes)) || Ln <- Out, length(Lexemes = string:lexemes(Ln, " ")) >= Col], @@ -106,41 +181,41 @@ rootset(Config) when is_list(Config) -> {ok, Scope} = pg:start_link(TestCase), Fun = fun () -> ok = pg:join(TestCase, lists:seq(1, 2), self()) end, %% rootset tests - {ok, Profile} = hprof:profile(Fun, #{rootset => [TestCase], report => return}), - TwoProcs = hprof:inspect(Profile), + {ok, Profile} = tprof:profile(Fun, #{rootset => [TestCase], report => return, type => call_memory}), + TwoProcs = tprof:inspect(Profile), ?assertEqual(2, maps:size(TwoProcs)), %% must be pg and "profiled process" %% now trace all processes, existing and new - {ok, ProfAll} = hprof:profile(Fun, #{rootset => processes, report => return}), - %% at least hprof, pg2 and new profiled processes are traced - ?assert(map_size(hprof:inspect(ProfAll)) >= 3), + {ok, ProfAll} = tprof:profile(Fun, #{rootset => processes, report => return, type => call_memory}), + %% at least tprof, pg2 and new profiled processes are traced + ?assert(map_size(tprof:inspect(ProfAll)) >= 3), gen_server:stop(Scope). set_on_spawn() -> - [{doc, "Tests hprof running with extra spawned processes"}]. + [{doc, "Tests tprof running with extra spawned processes"}]. set_on_spawn(Config) when is_list(Config) -> %% profile a function that spawns additional process - {done, Profile} = hprof:profile( + {done, Profile} = tprof:profile( fun () -> {Pid, MRef} = spawn_monitor(fun () -> lists:seq(1, 32) end), receive {'DOWN', MRef, process, Pid, normal} -> done end - end, #{report => return, set_on_spawn => false}), - {done, ProfileMFA} = hprof:profile(?MODULE, seq, [32], #{report => return, set_on_spawn => false}), + end, #{report => return, set_on_spawn => false, type => call_memory}), + {done, ProfileMFA} = tprof:profile(?MODULE, seq, [32], #{report => return, set_on_spawn => false, type => call_memory}), %% check totals - {_G1, TotalProfile} = hprof:inspect(Profile, total, words), - {_G2, TotalProfileMFA} = hprof:inspect(ProfileMFA, total, words), + #{all := {call_memory, _G1, TotalProfile}} = tprof:inspect(Profile, total, measurement), + #{all := {call_memory, _G2, TotalProfileMFA}} = tprof:inspect(ProfileMFA, total, measurement), %% only 1 process must be there - ?assertEqual(1, maps:size(hprof:inspect(Profile)), {set_on_spawn, Profile}), + ?assertEqual(1, maps:size(tprof:inspect(Profile)), {set_on_spawn, Profile}), %% check per-process stats case erlang:system_info(wordsize) of - 8 -> ?assertMatch({?MODULE, {_, 0}, 1, 9, 9, _}, lists:keyfind(?MODULE, 1, TotalProfile)); - 4 -> ?assertMatch({?MODULE, {_, 0}, 1, 10, 10, _}, lists:keyfind(?MODULE, 1, TotalProfile)) + 8 -> ?assertMatch({?MODULE, {_, 0}, 1, 9, 9.0, _}, lists:keyfind(?MODULE, 1, TotalProfile)); + 4 -> ?assertMatch({?MODULE, {_, 0}, 1, 10, 10.0, _}, lists:keyfind(?MODULE, 1, TotalProfile)) end, %% MFA takes 6 more words. This test should be improved to depend less on the internal %% implementation. case erlang:system_info(wordsize) of - 8 -> ?assertMatch({?MODULE, {seq, 1}, 1, 13, 13, _}, lists:keyfind(?MODULE, 1, TotalProfileMFA)); - 4 -> ?assertMatch({?MODULE, {seq, 1}, 1, 14, 14, _}, lists:keyfind(?MODULE, 1, TotalProfileMFA)) + 8 -> ?assertMatch({?MODULE, {seq, 1}, 1, 13, 13.0, _}, lists:keyfind(?MODULE, 1, TotalProfileMFA)); + 4 -> ?assertMatch({?MODULE, {seq, 1}, 1, 14, 14.0, _}, lists:keyfind(?MODULE, 1, TotalProfileMFA)) end. seq(Max) -> @@ -151,7 +226,7 @@ live_trace() -> [{doc, "Tests memory tracing for pre-existing processes"}]. live_trace(Config) when is_list(Config) -> - {ok, _Srv} = hprof:start_link(), + {ok, _Srv} = tprof:start_link(#{type => call_memory}), Pid = spawn_link( fun () -> receive @@ -160,46 +235,46 @@ live_trace(Config) when is_list(Config) -> From ! {self(), done} end end), - _ = hprof:set_pattern(?MODULE, '_', '_'), - 1 = hprof:enable_trace(Pid), + _ = tprof:set_pattern(?MODULE, '_', '_'), + 1 = tprof:enable_trace(Pid), Pid ! {self(), 12}, receive {Pid, done} -> ok end, - catch hprof:disable_trace(Pid), - Profile = hprof:collect(), - ProcInspected = hprof:inspect(Profile), + catch tprof:disable_trace(Pid), + Profile = tprof:collect(), + ProcInspected = tprof:inspect(Profile), %% white box check: list comprehension with 1-arity, and 100% allocation - %% hprof:format(user, ProcInspected), - #{Pid := {48, [{?MODULE, {_LC, 1}, 13, 48, 3, 100.0}]}} = ProcInspected, - hprof:stop(). + %% tprof:format(user, ProcInspected), + #{Pid := {call_memory, 48, [{?MODULE, {_LC, 1}, 13, 48, _, 100.0}]}} = ProcInspected, + tprof:stop(). patterns() -> [{doc, "Tests pattern enable/disable correctness"}]. patterns(Config) when is_list(Config) -> - {ok, _Srv} = hprof:start_link(), + {ok, _Srv} = tprof:start_link(#{type => call_memory}), %% test errors - ?assertEqual({error, {not_traced, pg, get_members, '_'}}, hprof:clear_pattern(pg, get_members, '_')), - ?assertEqual({error, {trace_pattern, ?MODULE, seq, 2}}, hprof:set_pattern(?MODULE, seq, 2)), + ?assertEqual({error, {not_traced, pg, get_members, '_'}}, tprof:clear_pattern(pg, get_members, '_')), + ?assertEqual({error, {trace_pattern, ?MODULE, seq, 2}}, tprof:set_pattern(?MODULE, seq, 2)), %% successful patterns - 1 = hprof:set_pattern(?MODULE, seq, 1), - 3 = hprof:set_pattern(?MODULE, pattern_fun, '_'), - 1 = hprof:clear_pattern(?MODULE, pattern_fun, 2), + 1 = tprof:set_pattern(?MODULE, seq, 1), + 3 = tprof:set_pattern(?MODULE, pattern_fun, '_'), + 1 = tprof:clear_pattern(?MODULE, pattern_fun, 2), Expected = [{pattern_fun, 1}, {pattern_fun, 3}, {seq, 1}], - ?assertEqual(#{?MODULE => Expected}, hprof:get_trace_map()), + ?assertEqual(#{?MODULE => Expected}, tprof:get_trace_map()), %% verify tracing flags verify_trace([{?MODULE, F, A} || {F, A} <- Expected], [{?MODULE, pattern_fun, 2}]), %% trace the entire lists module, and then exclude pattern_fun/1,2,3 and seq/1 - _ = hprof:set_pattern(?MODULE, '_', '_'), - 3 = hprof:clear_pattern(?MODULE, pattern_fun, '_'), - 1 = hprof:clear_pattern(?MODULE, seq, 1), + _ = tprof:set_pattern(?MODULE, '_', '_'), + 3 = tprof:clear_pattern(?MODULE, pattern_fun, '_'), + 1 = tprof:clear_pattern(?MODULE, seq, 1), Cleared = [{pattern_fun, 1}, {pattern_fun, 2}, {pattern_fun, 3}, {seq, 1}], Traced = ?MODULE:module_info(functions) -- Cleared, verify_trace([{?MODULE, F, A} || {F, A} <- Traced], [{?MODULE, F, A} || {F, A} <- Cleared]), %% clear all, which clears lists too - _ = hprof:clear_pattern('_', '_', '_'), + _ = tprof:clear_pattern('_', '_', '_'), verify_trace([], [{?MODULE, F, A} || {F, A} <- Traced ++ Cleared]), - ?assertEqual(#{}, hprof:get_trace_map()), - hprof:stop(). + ?assertEqual(#{}, tprof:get_trace_map()), + tprof:stop(). verify_trace(On, Off) -> [?assertEqual({call_memory, []}, erlang:trace_info(MFA, call_memory)) || MFA <- On], @@ -217,9 +292,9 @@ processes(Config) when is_list(Config) -> Pid2 = spawn_link(fun spawn_loop/0), register(?FUNCTION_NAME, Pid2), %% test a mix of pids/registered processes/single PID calls - ?assertEqual(2, hprof:enable_trace([Pid, Pid2])), - ?assertEqual(0, hprof:disable_trace('$sure_not_exist')), - ?assertEqual({1, ['$sure_not_exist']}, hprof:enable_trace([Pid, '$sure_not_exist'])), + ?assertEqual(2, tprof:enable_trace([Pid, Pid2])), + ?assertEqual(0, tprof:disable_trace('$sure_not_exist')), + ?assertEqual({1, ['$sure_not_exist']}, tprof:enable_trace([Pid, '$sure_not_exist'])), ok = gen:stop(Pid), ok = gen:stop(Pid2). @@ -232,18 +307,18 @@ server(Config) when is_list(Config) -> %% simulate existing process Pid = spawn_link(fun spawn_loop/0), %% start the profiler - {ok, Srv} = hprof:start_link(), + {ok, Srv} = tprof:start_link(#{type => call_memory}), %% test ad-hoc profile clash - ?assertException(error, {already_started, Srv}, hprof:profile(fun spawn_loop/0)), + ?assertException(error, {already_started, Srv}, tprof:profile(fun spawn_loop/0)), %% test live trace - 1 = hprof:set_pattern(?MODULE, dispatch, '_'), - _ = hprof:set_pattern(pg, '_', '_'), + 1 = tprof:set_pattern(?MODULE, dispatch, '_'), + _ = tprof:set_pattern(pg, '_', '_'), %% watch for pg traces and for our process - 2 = hprof:enable_trace([Pid, ?FUNCTION_NAME]), + 2 = tprof:enable_trace([Pid, ?FUNCTION_NAME]), %% run the traced operation _ = gen_server:call(Pid, {apply, pg, join, [?FUNCTION_NAME, group, Pid]}), %% collect profile (can save it to a file for later analysis) - FirstProfile = hprof:collect(), + {call_memory, FirstProfile} = tprof:collect(), %% must not be empty, and must contain 3-words dispatch from this module, %% and at least something from pg in two processes ?assertNotEqual([], FirstProfile), @@ -251,29 +326,30 @@ server(Config) when is_list(Config) -> ?assertMatch({pg, handle_call, 3, [{Scope, _, _}]}, lists:keyfind(handle_call, 2, FirstProfile)), ?assertMatch({pg, join, 3, [{Pid, _, _}]}, lists:keyfind(join, 2, FirstProfile)), %% pause tracing - ok = hprof:pause(), + ok = tprof:pause(), %% ensure paused by running more code but keeping the trace %% ensure collection still returns the previous result _ = gen_server:call(Pid, {apply, pg, join, [?FUNCTION_NAME, group, Pid]}), - ?assertEqual(FirstProfile, hprof:collect()), + {call_memory, FirstProfile} = tprof:collect(), %% continue, ensure new results are collected - ok = hprof:continue(), + ok = tprof:continue(), _ = gen_server:call(Pid, {apply, pg, leave, [?FUNCTION_NAME, group, [Pid, Pid]]}), - ?assertNotEqual(FirstProfile, hprof:collect()), + ?assertNotEqual({call_memory, FirstProfile}, tprof:collect()), %% restart all counters from zero and ensure that we again collect the original data - ok = hprof:restart(), + ok = tprof:restart(), _ = gen_server:call(Pid, {apply, pg, join, [?FUNCTION_NAME, group, Pid]}), - ?assertEqual(FirstProfile, hprof:collect()), + {call_memory, FirstProfile} = tprof:collect(), %% test ad-hoc profiling can be done while running server-aided %% for that, profiler should have very specific pattern - {_, AdHoc} = hprof:profile(lists, seq, [1, 32], #{registered => false, pattern => {lists, '_', '_'}, - report => return}), + {_, AdHoc} = tprof:profile(lists, seq, [1, 32], #{registered => false, pattern => {lists, '_', '_'}, + report => return, type => call_memory}), %% check totals: must be 64 words allocated by a single lists:seq_loop - ?assertMatch({64, [{lists, _, _, 64, _, _}]}, hprof:inspect(AdHoc, total, words)), + ?assertMatch(#{all := {call_memory, 64, [{lists, _, _, 64, _, _}]}}, + tprof:inspect(AdHoc, total, measurement)), %% verify that server-aided version still works - ?assertEqual(FirstProfile, hprof:collect()), - ok = hprof:stop(), + {call_memory, FirstProfile} = tprof:collect(), + ok = tprof:stop(), ok = gen_server:stop(Scope), ok = gen:stop(Pid). @@ -296,21 +372,21 @@ hierarchy() -> [{doc, "Tests tracing for process hierarchy"}]. hierarchy(Config) when is_list(Config) -> - {ok, _Srv} = hprof:start_link(), - Traced = hprof:enable_trace({all_children, kernel_sup}), + {ok, _Srv} = tprof:start_link(#{type => call_memory}), + Traced = tprof:enable_trace({all_children, kernel_sup}), ?assert(Traced > 5), - ?assert(hprof:set_pattern(code_server, '_', '_') > 5), + ?assert(tprof:set_pattern(code_server, '_', '_') > 5), _ = code:get_path(), %% makes a call to code_server %% disabling all processes tracing should return more than "children of" - ?assert(hprof:disable_trace(processes) > Traced), - Profile = hprof:collect(), - hprof:stop(), + ?assert(tprof:disable_trace(processes) > Traced), + {call_memory, Profile} = tprof:collect(), + tprof:stop(), ?assertNotEqual(false, lists:keyfind(handle_call, 2, Profile)). code_reload() -> [{doc, "Tests that collection does not fail for a hot-code-reloaded module"}]. code_reload(Config) when is_list(Config) -> - Sample = hprof:profile(fun () -> code:load_file(?MODULE) end, #{report => return}), + Sample = tprof:profile(fun () -> code:load_file(?MODULE) end, #{report => return, type => call_memory}), %% don't care about actual returned values, but do care that profile/2 does not crash ?assertNotEqual([], Sample). diff --git a/system/doc/efficiency_guide/profiling.xml b/system/doc/efficiency_guide/profiling.xml index 716614464a..f5506e8157 100644 --- a/system/doc/efficiency_guide/profiling.xml +++ b/system/doc/efficiency_guide/profiling.xml @@ -41,22 +41,14 @@ <p>Erlang/OTP contains several tools to help finding bottlenecks:</p> <list type="bulleted"> + <item><p><seeerl marker="tools:tprof"><c>tprof</c></seeerl> is + a tracing profiler that can measure call count, call time, or + heap allocations per function call.</p></item> + <item><p><seeerl marker="tools:fprof"><c>fprof</c></seeerl> provides the most detailed information about where the program time is spent, but it significantly slows down the program it profiles.</p></item> - <item><p><seeerl marker="tools:eprof"><c>eprof</c></seeerl> provides - time information of each function used in the program. No call graph is - produced, but <c>eprof</c> has considerably less impact on the program it - profiles.</p> - <p>If the program is too large to be profiled by <c>fprof</c> or - <c>eprof</c>, <c>cprof</c> can be used to locate code parts that - are to be more thoroughly profiled using <c>fprof</c> or <c>eprof</c>.</p></item> - - <item><p><seeerl marker="tools:cprof"><c>cprof</c></seeerl> is the - most lightweight tool, but it only provides execution counts on a - function basis (for all processes, not per process).</p></item> - <item><p><seeerl marker="runtime_tools:dbg"><c>dbg</c></seeerl> is the generic erlang tracing frontend. By using the <c>timestamp</c> or <c>cpu_timestamp</c> options it can be used to time how long function @@ -67,7 +59,6 @@ locking mechanisms. It is useful when looking for bottlenecks in interaction between process, port, ets tables and other entities that can be run in parallel.</p></item> - </list> <p>The tools are further described in diff --git a/system/doc/general_info/upcoming_incompatibilities.xml b/system/doc/general_info/upcoming_incompatibilities.xml index 3b818b54ca..aa5a813366 100644 --- a/system/doc/general_info/upcoming_incompatibilities.xml +++ b/system/doc/general_info/upcoming_incompatibilities.xml @@ -275,4 +275,18 @@ String Content <section> </section> + <section> + <title>OTP 29</title> + + <section> + <title>cprof and eprof will be replaced by tprof</title> + <p> + As of OTP 29, the <c>cprof</c> and <c>eprof</c> will be + removed in favor of + <seeerl marker="tools:tprof"><c>tprof</c></seeerl> added + in OTP 27. + </p> + </section> + </section> + </chapter> -- 2.35.3
Locations
Projects
Search
Status Monitor
Help
OpenBuildService.org
Documentation
API Documentation
Code of Conduct
Contact
Support
@OBShq
Terms
openSUSE Build Service is sponsored by
The Open Build Service is an
openSUSE project
.
Sign Up
Log In
Places
Places
All Projects
Status Monitor
