1/* Part of SWI-Prolog 2 3 Author: Jan Wielemaker 4 E-mail: jan@swi-prolog.org 5 WWW: http://www.swi-prolog.org 6 Copyright (c) 2023-2025, SWI-Prolog Solutions b.v. 7 All rights reserved. 8 9 Redistribution and use in source and binary forms, with or without 10 modification, are permitted provided that the following conditions 11 are met: 12 13 1. Redistributions of source code must retain the above copyright 14 notice, this list of conditions and the following disclaimer. 15 16 2. Redistributions in binary form must reproduce the above copyright 17 notice, this list of conditions and the following disclaimer in 18 the documentation and/or other materials provided with the 19 distribution. 20 21 THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 22 "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 23 LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS 24 FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE 25 COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, 26 INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, 27 BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; 28 LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER 29 CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT 30 LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN 31 ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE 32 POSSIBILITY OF SUCH DAMAGE. 33*/ 34 35:- module(prolog_profile, 36 [ profile/1, % :Goal 37 profile/2, % :Goal, +Options 38 show_profile/1, % +Options 39 profile_data/1, % -Dict 40 profile_procedure_data/2 % :PI, -Data 41 ]). 42:- autoload(library(error),[must_be/2]). 43:- autoload(library(lists), [member/2, append/3]). 44:- autoload(library(apply), [foldl/4]). 45:- autoload(library(option), [option/3]). 46:- autoload(library(pairs), [map_list_to_pairs/3, pairs_values/2]). 47:- autoload(library(prolog_code), [predicate_sort_key/2, predicate_label/2]). 48 49:- meta_predicate 50 profile(), 51 profile(, ), 52 profile_procedure_data(, ). 53 54:- create_prolog_flag(profile_ports, true, 55 [ keep(true), 56 type(oneof([true,false,classic])) 57 ]). 58:- create_prolog_flag(profile_exact, auto, 59 [ keep(true), 60 type(oneof([auto,true,false])) 61 ]). 62:- create_prolog_flag(profile_sample_rate, 200.0, 63 [ keep(true), 64 type(float) 65 ]). 66 67:- set_prolog_flag(generate_debug_info, false).
76:- multifile
77 prolog:show_profile_hook/1,
78 prolog:profile_node_label/2.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:
cpu or wall time. The default is CPU time.true, do not sample, but read the clock each time
execution moves to another node of the call tree. This gives
exact wall times, also for short running goals. For CPU time,
the thread's CPU time is read once per sample period (see
sample_rate(Rate)) and after each long interval, where the
thread may have been off the CPU. If auto, use exact
timing if reading the clock is cheap and, for CPU time, the
thread CPU clock is precise. This is typically not the case
in virtual machines. Otherwise use sampling. Default is
defined by the Prolog flag profile_exact, which defaults to
auto.profile_sample_rate,
which defaults to 200.true (all ports), false (call
port only) or classic (all with some errors).
Accomodates space/accuracy tradeoff building call tree.
Default is defined by the Prolog flag profile_ports,
which defaults to true.true (default false), show cumulative output in
a textual report.122profile(Goal) :- 123 profile(Goal, []). 124 125profile(Goal0, Options) :- 126 current_prolog_flag(profile_ports, DefPorts), 127 current_prolog_flag(profile_sample_rate, DefRate), 128 option(time(Which), Options, cpu), 129 time_name(Which, Time), 130 current_prolog_flag(profile_exact, DefExact), 131 option(exact(Exact0), Options, DefExact), 132 must_be(oneof([auto,true,false]), Exact0), 133 exact(Exact0, Time, Exact), 134 exact_time(Exact, Time, How), 135 option(ports(Ports), Options, DefPorts), 136 must_be(oneof([true,false,classic]),Ports), 137 option(sample_rate(Rate), Options, DefRate), 138 must_be(between(1.0,1000), Rate), 139 expand_goal(Goal0, Goal), 140 call_cleanup('$profile'(Goal, How, Ports, Rate), 141 prolog_statistics:show_profile(Options)). 142 143exact(auto, Time, Exact) :- 144 !, 145 ( time_clock(Time, Clock), 146 '$prof_exact_ok'(Clock) 147 -> Exact = true 148 ; Exact = false 149 ). 150exact(Exact, _, Exact). 151 152time_clock(cputime, cpu). 153time_clock(walltime, wall). 154 155exact_time(false, Time, Time). 156exact_time(true, Time, How) :- 157 exact_name(Time, How). 158 159exact_name(cputime, exact_cputime). 160exact_name(walltime, exact_walltime). 161 162time_name(cpu, cputime) :- !. 163time_name(wall, walltime) :- !. 164time_name(cputime, cputime) :- !. 165time_name(walltime, walltime) :- !. 166time_name(Time, _) :- 167 must_be(oneof([cpu,wall]), Time).
true (default false), show cumulative output in
a textual report.179show_profile(N) :- 180 integer(N), 181 !, 182 show_profile([top(N)]). 183show_profile(Options) :- 184 profiler(Old, false), 185 show_profile_(Options), 186 profiler(_, Old). 187 188show_profile_(Options) :- 189 prolog:show_profile_hook(Options), 190 !. 191show_profile_(Options) :- 192 show_text_profile(Options). 193 194% Textual report on the last collected profile. 195 196show_text_profile(Options) :- 197 prof_statistics(Stat), 198 NetTicks is Stat.ticks-Stat.accounting, 199 percentage(NetTicks, Stat.ticks, NetPC), 200 NetTime is NetPC*Stat.time/100, 201 Ports = Stat.ports, 202 findall(Node, procedure_data(_, Node), Nodes), 203 ( option(cumulative(false), Options, false) 204 -> SortKey = ticks_self 205 ; SortKey = ticks 206 ), 207 sort_prof_nodes(SortKey, Nodes, Sorted), 208 option(top(N), Options, 25), 209 top(N, Sorted, Top), 210 column_stops(Top, Ports, Stops), 211 Stops = stops(CallStop, RedoStop, ExitStop), 212 format_divider, 213 ( Stat.exact == true 214 -> Mode = 'exact ' 215 ; Mode = '' 216 ), 217 format('Number of nodes: ~w~t[~w~w time, ports(~w)]~60|~t\c 218 Total time: ~3f seconds~101|~n', 219 [Stat.nodes, Mode, Stat.clock, Ports, NetTime]), 220 format('Predicate~tCalls +~*| Redos~t~*|~t \c 221 Exits +~*| Fails~tTime:Self +~87| Time:Children~n', 222 [CallStop, RedoStop, ExitStop]), 223 format_divider, 224 forall(member(Node, Top), 225 show_plain(Node, (NetTicks,NetTime,Ports), Stops)), 226 format_divider. 227 228top(N, List, Top) :- 229 length(List, Len), 230 Len > N, 231 !, 232 length(Top, N), 233 append(Top, _, List). 234top(_, List, List). 235 236% column_stops(+Nodes, +Ports, -Stops) is det. 237% 238% The columns of the counts are as wide as their widest count in 239% Nodes. A column that is wider than the default moves the columns 240% left of it to the left, taking the space from the predicate labels. 241% Stops is stops(CallStop, RedoStop, ExitStop), the column where the 242% calls, redos and exits end. 243 244column_stops(Nodes, Ports, stops(CallStop, RedoStop, ExitStop)) :- 245 foldl(count_widths(Ports), Nodes, 0-0-0, RW-EW-FW), 246 ExitStop is 58 - max(0, FW-10), 247 RedoStop is ExitStop - 9 - max(0, EW-7), 248 CallStop is RedoStop - 8 - max(0, RW-6). 249 250count_widths(Ports, Node, R0-E0-F0, R-E-F) :- 251 counts(Node, Ports, _Call, Redo, Exit, Fail), 252 count_width(Redo, RW), R is max(R0, RW), 253 count_width(Exit, EW), E is max(E0, EW), 254 count_width(Fail, FW), F is max(F0, FW). 255 256count_width(Count, Width) :- 257 format(string(S), '~D', [Count]), 258 string_length(S, Width). 259 260counts(Node, Ports, Call, Redo, Exit, Fail) :- 261 value(call, Node, Call), 262 ( Ports == false 263 -> Redo = 0, Exit = 0, Fail = 0 264 ; value(redo, Node, Redo), 265 value(exit, Node, Exit), 266 Fail is Call+Redo-Exit 267 ). 268 269sort_prof_nodes(ticks, Nodes, Sorted) :- 270 !, 271 map_list_to_pairs(key_ticks, Nodes, Keyed), 272 sort(1, >=, Keyed, KeySorted), 273 pairs_values(KeySorted, Sorted). 274sort_prof_nodes(Key, Nodes, Sorted) :- 275 sort(Key, >=, Nodes, Sorted). 276 277key_ticks(Node, Ticks) :- 278 value(ticks,Node,Ticks). 279 280show_plain(Node, (NetTicks,NetTime,Ports), 281 stops(CallStop, RedoStop, ExitStop)) :- 282 value(label, Node, Label), 283 counts(Node, Ports, Call, Redo, Exit, Fail), 284 count_width(Call, CallsWidth), 285 Width is CallStop - CallsWidth - 3, % " " before and " +" after Calls 286 elide(Label, Width, Pred), 287 time_data(Node,NetTicks,NetTime,SelfPC,SelfTime,ChildrenPC,ChildrenTime), 288 format('~w ~t~D +~*| ~D ~t~*|~t~D +~*| ~D ~t~2fs.(~78|~t~1f%) +~87|~t~2fs.(~95|~t~1f%)~102|~n', 289 [ Pred, Call, CallStop, Redo, RedoStop, Exit, ExitStop, Fail, 290 SelfTime, SelfPC, ChildrenTime, ChildrenPC 291 ]). 292 293format_divider :- format('~`=t~102|~n').
300elide(Label, Width, Elided) :- 301 string_length(Label, Len), 302 Len > Width, 303 !, 304 ellipsis(Ellipsis), 305 string_length(Ellipsis, ELen), 306 Keep is max(0, Width-ELen), 307 Pre is Keep//2, 308 Post is Keep-Pre, 309 sub_string(Label, 0, Pre, _, S1), 310 sub_string(Label, _, Post, 0, S2), 311 atomics_to_string([S1, Ellipsis, S2], Elided). 312elide(Label, _, Label). 313 314ellipsis("\u2026") :- 315 stream_property(current_output, encoding(Enc)), 316 unicode_encoding(Enc), 317 !. 318ellipsis("..."). 319 320unicode_encoding(utf8). 321unicode_encoding(unicode_be). 322unicode_encoding(unicode_le). 323unicode_encoding(wchar_t). 324 325time_data(Data,NetTicks,NetTime,SelfPC,SelfTime,ChildrenPC,ChildrenTime) :- 326 value(ticks_self,Data,Ticks), 327 percentage(Ticks, NetTicks, SelfPC), 328 SelfTime is SelfPC*NetTime/100, 329 value(ticks_siblings,Data,ChildrenTicks), 330 percentage(ChildrenTicks, NetTicks, ChildrenPC), 331 ChildrenTime is ChildrenPC*NetTime/100. 332 333% Percentage of Part in Total. Total is 0 if no sample was taken. 334 335percentage(_, Total, 0.0) :- 336 Total =:= 0, 337 !. 338percentage(Part, Total, Percent) :- 339 Percent is 100*Part/Total. 340 341 342 /******************************* 343 * DATA GATHERING * 344 *******************************/
exact
is true, the number of times execution moved to another
node of the call tree.true, false or classiccpu or wall, the time that was profiled.exact(true)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)
397profile_data(Data) :- 398 setup_call_cleanup( 399 profiler(Old, false), 400 profile_data_(Data), 401 profiler(_, Old)). 402 403profile_data_(profile{summary:Summary, nodes:Nodes}) :- 404 prof_statistics(Summary), 405 findall(Node, procedure_data(_, Node), Nodes).
413prof_statistics(summary{samples:Samples, ticks:Ticks, 414 accounting:Account, time:Time, 415 nodes:Nodes, 416 sample_period: Period, 417 ports: Ports, 418 clock: Clock, 419 exact: Exact 420 }) :- 421 '$prof_statistics'(Samples, Ticks, Account, Time, Nodes, Period, Ports, 422 Mode), 423 prof_mode(Mode, Clock, Exact). 424 425prof_mode(cputime, cpu, false). 426prof_mode(walltime, wall, false). 427prof_mode(exact_cputime, cpu, true). 428prof_mode(exact_walltime, wall, true). 429prof_mode(false, cpu, false). % no data
nodes key.437profile_procedure_data(Pred, Node) :- 438 procedure_data(Pred, Node). 439 440% procedure_data(?Pred, -Data:dict) is nondet. 441% 442% As profile_procedure_data/2, but if Pred is unbound, also enumerate 443% the nodes of other profile types such as XPCE methods. These are 444% not qualified. 445 446procedure_data(Pred, Node) :- 447 Node = node{predicate:Pred, 448 ticks_self:TicksSelf, ticks_siblings:TicksSiblings, 449 call:Call, redo:Redo, exit:Exit, 450 callers:Parents, callees:Siblings}, 451 ( specified(Pred) 452 -> true 453 ; profiled_predicates(Preds), 454 member(Pred, Preds) 455 ), 456 '$prof_procedure_data'(Pred, 457 TicksSelf, TicksSiblings, 458 Call, Redo, Exit, 459 Parents, Siblings). 460 461specified(Module:Head) :- 462 atom(Module), 463 callable(Head). 464 465profiled_predicates(Preds) :- 466 setof(Pred, prof_impl(Pred), Preds). 467 468prof_impl(Pred) :- 469 prof_node_id(Node), 470 node_id_pred(Node, Pred). 471 472prof_node_id(N) :- 473 prof_node_id_below(N, -). 474 475prof_node_id_below(N, Root) :- 476 '$prof_sibling_of'(N0, Root), 477 ( N = N0 478 ; prof_node_id_below(N, N0) 479 ). 480 481node_id_pred(Node, Pred) :- 482 '$prof_node'(Node, Pred, _Calls, _Redos, _Exits, _Recur, 483 _Ticks, _SiblingTicks).
492node_label(Pred, Label) :- 493 prolog:profile_node_label(Pred, Label), 494 !. 495node_label(Pred, Label) :- 496 ground(Pred), 497 Pred = _:_, 498 !, 499 predicate_label(Pred, Label). 500node_label(Pred, Label) :- 501 format(string(Label), '~p', [Pred]).
507value(name, Data, Name) :- 508 !, 509 predicate_sort_key(Data.predicate, Name). 510value(label, Data, Label) :- 511 !, 512 node_label(Data.predicate, Label). 513value(ticks, Data, Ticks) :- 514 !, 515 Ticks is Data.ticks_self + Data.ticks_siblings. 516value(time(Key, percentage, TotalTicks), Data, Percent) :- 517 !, 518 value(Key, Data, Ticks), 519 (TotalTicks > 0 520 -> Percent is 100 * (Ticks/TotalTicks) 521 ; Percent is 0.0 522 ). 523value(Name, Data, Value) :- 524 Value = Data.Name
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).