1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319
|
/* Part of SWI-Prolog
Author: Jan Wielemaker
E-mail: jan@swi-prolog.org
WWW: http://www.swi-prolog.org
Copyright (c) 2023, SWI-Prolog Solutions b.v.
All rights reserved.
Redistribution and use in source and binary forms, with or without
modification, are permitted provided that the following conditions
are met:
1. Redistributions of source code must retain the above copyright
notice, this list of conditions and the following disclaimer.
2. Redistributions in binary form must reproduce the above copyright
notice, this list of conditions and the following disclaimer in
the documentation and/or other materials provided with the
distribution.
THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER
CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN
ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
POSSIBILITY OF SUCH DAMAGE.
*/
:- module(prolog_profile,
[ profile/1, % :Goal
profile/2, % :Goal, +Options
show_profile/1, % +Options
profile_data/1, % -Dict
profile_procedure_data/2 % :PI, -Data
]).
:- autoload(library(error),[must_be/2]).
:- autoload(library(lists), [member/2]).
:- autoload(library(option), [option/3]).
:- autoload(library(pairs), [map_list_to_pairs/3, pairs_values/2]).
:- autoload(library(prolog_code), [predicate_sort_key/2, predicate_label/2]).
:- meta_predicate
profile(0),
profile(0, +),
profile_procedure_data(:, -).
:- set_prolog_flag(generate_debug_info, false).
/** <module> Execution profiler
This module provides a simple frontend on the execution profiler with a
hook to the GUI visualiser for profiling results defined in
library(swi/pce_profile).
*/
:- multifile
prolog:show_profile_hook/1.
%! profile(:Goal).
%! profile(:Goal, +Options).
%
% Run once(Goal) under the execution profiler. If the (xpce) GUI is
% enabled this predicate is hooked by library(swi/pce_profile) and
% results are presented in a gui that enables navigating the call tree
% and jump to predicate implementations. Without the GUI, a simple
% textual report is generated. Defined options are:
%
% * time(Which)
% Profile `cpu` or `wall` time. The default is CPU time.
% * sample_rate(Rate)
% Samples per second, any numeric value between 1 and 1000
% * ports(Bool)
% Specifies ports counted - `true` (all ports), `false` (call
% port only) or `classic` (all with some errors).
% Accomodates space/accuracy tradeoff building call tree.
% * top(N)
% When generating a textual report, show the top N predicates.
% * cumulative(Bool)
% If `true` (default `false`), show cumulative output in
% a textual report.
%
% @tbd The textual input reflects only part of the information.
% @see show_coverage/2 from library(test_cover).
profile(Goal) :-
profile(Goal, []).
profile(Goal0, Options) :-
option(time(Which), Options, cpu),
time_name(Which, How),
option(ports(Ports), Options, classic),
must_be(oneof([true,false,classic]),Ports),
option(sample_rate(Rate), Options, 200),
must_be(between(1.0,1000), Rate),
expand_goal(Goal0, Goal),
call_cleanup('$profile'(Goal, How, Ports, Rate),
prolog_statistics:show_profile(Options)).
time_name(cpu, cputime) :- !.
time_name(wall, walltime) :- !.
time_name(cputime, cputime) :- !.
time_name(walltime, walltime) :- !.
time_name(Time, _) :-
must_be(oneof([cpu,wall]), Time).
%! show_profile(+Options)
%
% Display last collected profiling data. Options are
%
% * top(N)
% When generating a textual report, show the top N predicates.
% * cumulative(Bool)
% If =true= (default =false=), show cumulative output in
% a textual report.
show_profile(N) :-
integer(N),
!,
show_profile([top(N)]).
show_profile(Options) :-
profiler(Old, false),
show_profile_(Options),
profiler(_, Old).
show_profile_(Options) :-
prolog:show_profile_hook(Options),
!.
show_profile_(Options) :-
prof_statistics(Stat),
sort_on(Options, SortKey),
findall(Node, profile_procedure_data(_:_, Node), Nodes),
sort_prof_nodes(SortKey, Nodes, Sorted),
format('~`=t~69|~n'),
format('Total time: ~3f seconds~n', [Stat.time]),
format('~`=t~69|~n'),
format('~w~t~w =~45|~t~w~60|~t~w~69|~n',
[ 'Predicate', 'Box Entries', 'Calls+Redos', 'Time'
]),
format('~`=t~69|~n'),
option(top(N), Options, 25),
show_plain(Sorted, N, Stat, SortKey).
sort_on(Options, ticks_self) :-
option(cumulative(false), Options, false),
!.
sort_on(_, ticks).
sort_prof_nodes(ticks, Nodes, Sorted) :-
!,
map_list_to_pairs(key_ticks, Nodes, Keyed),
sort(1, >=, Keyed, KeySorted),
pairs_values(KeySorted, Sorted).
sort_prof_nodes(Key, Nodes, Sorted) :-
sort(Key, >=, Nodes, Sorted).
key_ticks(Node, Ticks) :-
Ticks is Node.ticks_self + Node.ticks_siblings.
show_plain([], _, _, _).
show_plain(_, 0, _, _) :- !.
show_plain([H|T], N, Stat, Key) :-
show_plain(H, Stat, Key),
N2 is N - 1,
show_plain(T, N2, Stat, Key).
show_plain(Node, Stat, Key) :-
value(label, Node, Pred),
value(call, Node, Call),
value(redo, Node, Redo),
value(time(Key, percentage, Stat), Node, Percent),
IntPercent is round(Percent*10),
Entry is Call + Redo,
format('~w~t~D =~45|~t~D+~55|~D ~t~1d%~69|~n',
[Pred, Entry, Call, Redo, IntPercent]).
/*******************************
* DATA GATHERING *
*******************************/
%! profile_data(-Data) is det.
%
% Gather all relevant data from profiler. This predicate may be called
% while profiling is active in which case it is suspended while
% collecting the data. Data is a dict providing the following fields:
%
% - summary:Dict
% Overall statistics providing
% - samples:Count:
% Times the statistical profiler was called
% - ticks:Count
% Virtual ticks during profiling
% - accounting:Count
% Tick spent on accounting
% - time:Seconds
% Total time sampled
% - nodes:Count
% Nodes in the call graph.
% - sample_period: MicroSeconds
% Same interval timer period in micro seconds
% - ports: Ports
% One of `true`, `false` or `classic`
% - nodes
% List of nodes. Each node provides:
% - predicate:PredicateIndicator
% - ticks_self:Count
% - ticks_siblings:Count
% - call:Count
% - redo:Count
% - exit:Count
% - callers:list_of(Relative)
% - callees:list_of(Relative)
%
% _Relative_ is a term of the shape below that represents a caller or
% callee. Future versions are likely to use a dict instead.
%
% node(PredicateIndicator, CycleID, Ticks, TicksSiblings,
% Calls, Redos, Exits)
profile_data(Data) :-
setup_call_cleanup(
profiler(Old, false),
profile_data_(Data),
profiler(_, Old)).
profile_data_(profile{summary:Summary, nodes:Nodes}) :-
prof_statistics(Summary),
findall(Node, profile_procedure_data(_:_, Node), Nodes).
%! prof_statistics(-Node) is det.
%
% Get overall statistics
%
% @param Node term of the format prof(Ticks, Account, Time, Nodes)
prof_statistics(summary{samples:Samples, ticks:Ticks,
accounting:Account, time:Time,
nodes:Nodes,
sample_period: Period,
ports: Ports
}) :-
'$prof_statistics'(Samples, Ticks, Account, Time, Nodes, Period, Ports).
%! profile_procedure_data(?Pred, -Data:dict) is nondet.
%
% Collect data for Pred. If Pred is unbound data for each predicate
% that has profile data available is returned. Data is described in
% profile_data/1 as an element of the `nodes` key.
profile_procedure_data(Pred, Node) :-
Node = node{predicate:Pred,
ticks_self:TicksSelf, ticks_siblings:TicksSiblings,
call:Call, redo:Redo, exit:Exit,
callers:Parents, callees:Siblings},
( specified(Pred)
-> true
; profiled_predicates(Preds),
member(Pred, Preds)
),
'$prof_procedure_data'(Pred,
TicksSelf, TicksSiblings,
Call, Redo, Exit,
Parents, Siblings).
specified(Module:Head) :-
atom(Module),
callable(Head).
profiled_predicates(Preds) :-
setof(Pred, prof_impl(Pred), Preds).
prof_impl(Pred) :-
prof_node_id(Node),
node_id_pred(Node, Pred).
prof_node_id(N) :-
prof_node_id_below(N, -).
prof_node_id_below(N, Root) :-
'$prof_sibling_of'(N0, Root),
( N = N0
; prof_node_id_below(N, N0)
).
node_id_pred(Node, Pred) :-
'$prof_node'(Node, Pred, _Calls, _Redos, _Exits, _Recur,
_Ticks, _SiblingTicks).
%! value(+Key, +NodeData, -Value)
%
% Obtain possible computed attributes from NodeData.
value(name, Data, Name) :-
!,
predicate_sort_key(Data.predicate, Name).
value(label, Data, Label) :-
!,
predicate_label(Data.predicate, Label).
value(ticks, Data, Ticks) :-
!,
Ticks is Data.ticks_self + Data.ticks_siblings.
value(time(Key, percentage, Stat), Data, Percent) :-
!,
value(Key, Data, Ticks),
Total = Stat.ticks,
Account = Stat.accounting,
( Total-Account > 0
-> Percent is 100 * (Ticks/(Total-Account))
; Percent is 0.0
).
value(Name, Data, Value) :-
Value = Data.Name.
|