View source with raw comments or as raw
    1/*  Part of SWI-Prolog
    2
    3    Author:        Jan Wielemaker
    4    E-mail:        J.Wielemaker@vu.nl
    5    WWW:           http://www.swi-prolog.org
    6    Copyright (c)  1999-2023, University of Amsterdam
    7                              VU University Amsterdam
    8                              CWI, Amsterdam
    9                              SWI-Prolog Solutions b.v.
   10    All rights reserved.
   11
   12    Redistribution and use in source and binary forms, with or without
   13    modification, are permitted provided that the following conditions
   14    are met:
   15
   16    1. Redistributions of source code must retain the above copyright
   17       notice, this list of conditions and the following disclaimer.
   18
   19    2. Redistributions in binary form must reproduce the above copyright
   20       notice, this list of conditions and the following disclaimer in
   21       the documentation and/or other materials provided with the
   22       distribution.
   23
   24    THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
   25    "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
   26    LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
   27    FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
   28    COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
   29    INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
   30    BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
   31    LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER
   32    CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
   33    LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN
   34    ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
   35    POSSIBILITY OF SUCH DAMAGE.
   36*/
   37
   38:- module(prolog_statistics,
   39          [ statistics/0,
   40            statistics/1,               % -Stats
   41            thread_statistics/2,        % ?Thread, -Stats
   42            time/1,                     % :Goal
   43            call_time/2,                % :Goal, -Time
   44            call_time/3                 % :Goal, -Time, -Result
   45          ]).   46:- autoload(library(pairs),[map_list_to_pairs/3]).   47
   48:- set_prolog_flag(generate_debug_info, false).   49
   50:- meta_predicate
   51    time(0),
   52    call_time(0, -, -),
   53    call_time(0, -).

Get information about resource usage

This library provides predicates to obtain information about resource usage by your program. The predicates of this library are for human use at the toplevel: information is printed. All predicates obtain their information using public low-level primitives. These primitives can be use to obtain selective statistics during execution. */

 statistics is det
Print information about resource usage using print_message/2.
See also
- All statistics printed are obtained through statistics/2.
   70statistics :-
   71    phrase(collect_stats, Stats),
   72    print_message(information, statistics(Stats)).
 statistics(-Stats:dict) is det
Stats is a dict representing the same information as statistics/0. This convience function is primarily intended to pass statistical information to e.g., a web client. Time critical code that wishes to collect statistics typically only need a small subset and should use statistics/2 to obtain exactly the data they need.
   83statistics(Stats) :-
   84    phrase(collect_stats, [CoreStats|StatList]),
   85    dict_pairs(CoreStats, _, CorePairs),
   86    map_list_to_pairs(dict_key, StatList, ExtraPairs),
   87    append(CorePairs, ExtraPairs, Pairs),
   88    dict_pairs(Stats, statistics, Pairs).
   89
   90dict_key(Dict, Key) :-
   91    gc{type:atom} :< Dict,
   92    !,
   93    Key = agc.
   94dict_key(Dict, Key) :-
   95    gc{type:clause} :< Dict,
   96    !,
   97    Key = cgc.
   98dict_key(Dict, Key) :-
   99    is_dict(Dict, Key).
  100
  101collect_stats -->
  102    core_statistics,
  103    gc_statistics,
  104    agc_statistics,
  105    cgc_statistics,
  106    shift_statistics,
  107    thread_counts,
  108    engine_counts.
  109
  110core_statistics -->
  111    { statistics(process_cputime, Cputime),
  112      statistics(process_epoch, Epoch),
  113      statistics(inferences, Inferences),
  114      statistics(atoms, Atoms),
  115      statistics(functors, Functors),
  116      statistics(predicates, Predicates),
  117      statistics(modules, Modules),
  118      statistics(codes, Codes),
  119      thread_self(Me),
  120      thread_stack_statistics(Me, Stacks)
  121    },
  122    [ core{ time:time{cpu:Cputime, inferences:Inferences, epoch:Epoch},
  123            data:counts{atoms:Atoms, functors:Functors,
  124                        predicates:Predicates, modules:Modules,
  125                        vm_codes:Codes},
  126            stacks:Stacks
  127          }
  128    ].
  129
  130:- if(\+current_predicate(thread_statistics/3)).  131thread_statistics(_Thread, Key, Value) :-       % single threaded version
  132    statistics(Key, Value).
  133:- endif.  134
  135thread_stack_statistics(Thread,
  136                  stacks{local:stack{name:local,
  137                                     allocated:Local,
  138                                     usage:LocalUsed},
  139                         global:stack{name:global,
  140                                      allocated:Global,
  141                                      usage:GlobalUsed},
  142                         trail:stack{name:trail,
  143                                     allocated:Trail,
  144                                     usage:TrailUsed},
  145                         total:stack{name:stacks,
  146                                     limit:StackLimit,
  147                                     allocated:StackAllocated,
  148                                     usage:StackUsed}
  149                        }) :-
  150    thread_statistics(Thread, trail,       Trail),
  151    thread_statistics(Thread, trailused,   TrailUsed),
  152    thread_statistics(Thread, local,       Local),
  153    thread_statistics(Thread, localused,   LocalUsed),
  154    thread_statistics(Thread, global,      Global),
  155    thread_statistics(Thread, globalused,  GlobalUsed),
  156    thread_statistics(Thread, stack_limit, StackLimit), %
  157    StackUsed is LocalUsed+GlobalUsed+TrailUsed,
  158    StackAllocated is Local+Global+Trail.
  159
  160gc_statistics -->
  161    { statistics(collections, Collections),
  162      Collections > 0,
  163      !,
  164      statistics(collected, Collected),
  165      statistics(gctime, GcTime)
  166    },
  167    [ gc{type:stack, unit:byte,
  168         count:Collections, time:GcTime, gained:Collected } ].
  169gc_statistics --> [].
  170
  171agc_statistics -->
  172    { catch(statistics(agc, Agc), _, fail),
  173      Agc > 0,
  174      !,
  175      statistics(agc_gained, Gained),
  176      statistics(agc_time, Time)
  177    },
  178    [ gc{type:atom, unit:atom,
  179         count:Agc, time:Time, gained:Gained} ].
  180agc_statistics --> [].
  181
  182cgc_statistics -->
  183    { catch(statistics(cgc, Cgc), _, fail),
  184      Cgc > 0,
  185      !,
  186      statistics(cgc_gained, Gained),
  187      statistics(cgc_time, Time)
  188    },
  189    [ gc{type:clause, unit:clause,
  190         count:Cgc, time:Time, gained:Gained} ].
  191cgc_statistics --> [].
  192
  193shift_statistics -->
  194    { statistics(local_shifts, LS),
  195      statistics(global_shifts, GS),
  196      statistics(trail_shifts, TS),
  197      (   LS > 0
  198      ;   GS > 0
  199      ;   TS > 0
  200      ),
  201      !,
  202      statistics(shift_time, Time)
  203    },
  204    [ shift{local:LS, global:GS, trail:TS, time:Time} ].
  205shift_statistics --> [].
  206
  207thread_counts -->
  208    { current_prolog_flag(threads, true),
  209      statistics(threads, Active),
  210      statistics(threads_created, Created),
  211      Created > 1,
  212      !,
  213      statistics(thread_cputime, CpuTime),
  214      Finished is Created - Active
  215    },
  216    [ thread{count:Active, finished:Finished, time:CpuTime} ].
  217thread_counts --> [].
  218
  219engine_counts -->
  220    { current_prolog_flag(threads, true),
  221      statistics(engines, Active),
  222      statistics(engines_created, Created),
  223      Created > 0,
  224      !,
  225      Finished is Created - Active
  226    },
  227    [ engine{count:Active, finished:Finished} ].
  228engine_counts --> [].
 thread_statistics(?Thread, -Stats:dict) is nondet
Obtain statistical information about a single thread. Fails silently of the Thread is no longer alive.
Arguments:
Stats- is a dict containing status, time and stack-size information about Thread.
  239thread_statistics(Thread, Stats) :-
  240    thread_property(Thread, status(Status)),
  241    human_thread_id(Thread, Id),
  242    Error = error(_,_),
  243    (   catch(thread_stats(Thread, Stacks, Time), Error, fail)
  244    ->  Stats = thread{id:Id,
  245                       status:Status,
  246                       time:Time,
  247                       stacks:Stacks}
  248    ;   Stats = thread{id:Thread,
  249                       status:Status}
  250    ).
  251
  252human_thread_id(Thread, Id) :-
  253    atom(Thread),
  254    !,
  255    Id = Thread.
  256human_thread_id(Thread, Id) :-
  257    thread_property(Thread, id(Id)).
  258
  259thread_stats(Thread, Stacks,
  260             time{cpu:CpuTime,
  261                  inferences:Inferences,
  262                  epoch:Epoch
  263                 }) :-
  264    thread_statistics(Thread, cputime, CpuTime),
  265    thread_statistics(Thread, inferences, Inferences),
  266    thread_statistics(Thread, epoch, Epoch),
  267    thread_stack_statistics(Thread, Stacks).
 time(:Goal) is nondet
Execute Goal, reporting statistics to the user. If Goal succeeds non-deterministically, retrying reports the statistics for providing the next answer.

Statistics are retrieved using thread_statistics/3 on the calling thread. Note that not all systems support thread-specific CPU time. Notable, this is lacking on MacOS X.

See also
- statistics/2 for obtaining statistics in your program and understanding the reported values.
- call_time/2, call_time/3 to obtain the timing in a dict.
bug
- Inference statistics are often a few off.
  285time(Goal) :-
  286    time_state(State0),
  287    (   call_cleanup(catch(Goal, E, (report(State0,10), throw(E))),
  288                     Det = true),
  289        time_true_report(State0),
  290        (   Det == true
  291        ->  !
  292        ;   true
  293        )
  294    ;   report(State0, 11),
  295        fail
  296    ).
 call_time(:Goal, -Time:dict)
 call_time(:Goal, -Time:dict, -Result)
Call Goal as call/1, unifying Time with a dict that provides information on the resource usage. If Goal succeeds with a choice point, backtracking reports the time used to find the next answer, failure or exception. If Goal succeeds deterministically no choice point is left open. Currently Time contains the keys below. Future versions may provide additional keys.

call_time/2 is defined as below. Note that for call_time/2 the time is only available if Goal succeeds.

call_time(Goal, Time) :-
    call_time(Goal, Time, Result),
    call(Result).
Arguments:
Result- is one of true, false or throw(E), depending on whether or not the goal succeeded or raised an exception. Note that Result may be called using call/1 to propagate the failure or exception.
  324call_time(Goal, Time) :-
  325    call_time(Goal, Time, Result),
  326    call(Result).
  327
  328call_time(Goal, Time, Result) :-
  329    time_state(State0),
  330    (   call_cleanup(catch(Goal, E, true),
  331                     Det = true),
  332        time_true_used(State0, Time),
  333        (   var(E)
  334        ->  Result = true,
  335            (   Det == true
  336            ->  !
  337            ;   true
  338            )
  339        ;   !,
  340            Result = throw(E)
  341        )
  342    ;   time_used(State0, 11, Time),
  343        Result = false
  344    ).
  345
  346report(State0, Sub) :-
  347    time_used(State0, Sub, time{wall:Wall, cpu:Time, inferences:Inferences}),
  348    (   Time =:= 0
  349    ->  Lips = 'Infinite'
  350    ;   Lips is integer(Inferences/Time)
  351    ),
  352    print_message(information, time(Inferences, Time, Wall, Lips)).
  353
  354time_used(time{wall:OldWall, cpu:OldTime, inferences:OldInferences}, Sub,
  355          time{wall:Wall, cpu:Time, inferences:Inferences}) :-
  356    time_state(time{wall:NewWall, cpu:NewTime, inferences:NewInferences}),
  357    Time       is NewTime - OldTime,
  358    Inferences is NewInferences - OldInferences - Sub,
  359    Wall       is NewWall - OldWall.
  360
  361time_state(time{wall:Wall, cpu:Time, inferences:Inferences}) :-
  362    get_time(Wall),
  363    statistics(cputime, Time),
  364    statistics(inferences, Inferences).
  365
  366time_true_report(State) :-             % leave choice-point
  367    report(State, 12).
  368time_true_report(State) :-
  369    time_true(State).
  370
  371time_true_used(State, Time) :-         % leave choice-point
  372    time_used(State, 12, Time).
  373time_true_used(State, _) :-
  374    time_true(State).
  375
  376
  377time_true(State) :-
  378    get_time(Wall),
  379    statistics(cputime, Time),
  380    statistics(inferences, Inferences0),
  381    Inferences is Inferences0 - 5,
  382    nb_set_dict(wall, State, Wall),
  383    nb_set_dict(cpu, State, Time),
  384    nb_set_dict(inferences, State, Inferences),
  385    fail.
  386
  387
  388                 /*******************************
  389                 *            MESSAGES          *
  390                 *******************************/
  391
  392:- multifile
  393    prolog:message/3.  394
  395% NOTE: The code below uses get_dict/3 rather than the functional
  396% notation to make this code work with `swipl --traditional`
  397
  398prolog:message(time(UsedInf, UsedTime, Wall, Lips)) -->
  399    [ '~D inferences, ~3f CPU in ~3f seconds (~w% CPU, ~w Lips)'-
  400      [UsedInf, UsedTime, Wall, Perc, Lips] ],
  401    {   Wall > 0
  402    ->  Perc is round(100*UsedTime/Wall)
  403    ;   Perc = ?
  404    }.
  405prolog:message(statistics(List)) -->
  406    msg_statistics(List).
  407
  408msg_statistics([]) --> [].
  409msg_statistics([H|T]) -->
  410    { is_dict(H, Tag) },
  411    msg_statistics(Tag, H),
  412    (   { T == [] }
  413    ->  []
  414    ;   [nl], msg_statistics(T)
  415    ).
  416
  417msg_statistics(core, S) -->
  418    { get_dict(time, S, Time),
  419      get_dict(data, S, Data),
  420      get_dict(stacks, S, Stacks)
  421    },
  422    time_stats(Time), [nl],
  423    data_stats(Data), [nl,nl],
  424    stacks_stats(Stacks).
  425msg_statistics(gc, S) -->
  426    {   (   get_dict(type, S, stack)
  427        ->  Label = ''
  428        ;   get_dict(type, S, Type),
  429            string_concat(Type, " ", Label)
  430        ),
  431        get_dict(count, S, Count),
  432        get_dict(gained, S, Gained),
  433        get_dict(unit, S, Unit),
  434        get_dict(time, S, Time)
  435    },
  436    [ '~D ~wgarbage collections gained ~D ~ws in ~3f seconds.'-
  437      [ Count, Label, Gained, Unit, Time]
  438    ].
  439msg_statistics(shift, S) -->
  440    { get_dict(local, S, Local),
  441      get_dict(global, S, Global),
  442      get_dict(trail, S, Trail),
  443      get_dict(time, S, Time)
  444    },
  445    [ 'Stack shifts: ~D local, ~D global, ~D trail in ~3f seconds'-
  446      [ Local, Global, Trail, Time ]
  447    ].
  448msg_statistics(thread, S) -->
  449    { get_dict(count, S, Count),
  450      get_dict(finished, S, Finished),
  451      get_dict(time, S, Time)
  452    },
  453    [ '~D threads, ~D finished threads used ~3f seconds'-
  454      [Count, Finished, Time]
  455    ].
  456msg_statistics(engine, S) -->
  457    { get_dict(count, S, Count),
  458      get_dict(finished, S, Finished)
  459    },
  460    [ '~D engines, ~D finished engines'-
  461      [Count, Finished]
  462    ].
  463
  464time_stats(T) -->
  465    { get_dict(epoch, T, Epoch),
  466      format_time(string(EpochS), '%+', Epoch),
  467      get_dict(cpu, T, CPU),
  468      get_dict(inferences, T, Inferences)
  469    },
  470    [ 'Started at ~s'-[EpochS], nl,
  471      '~3f seconds cpu time for ~D inferences'-
  472      [ CPU, Inferences ]
  473    ].
  474data_stats(C) -->
  475    { get_dict(atoms, C, Atoms),
  476      get_dict(functors, C, Functors),
  477      get_dict(predicates, C, Predicates),
  478      get_dict(modules, C, Modules),
  479      get_dict(vm_codes, C, VMCodes)
  480    },
  481    [ '~D atoms, ~D functors, ~D predicates, ~D modules, ~D VM-codes'-
  482      [ Atoms, Functors, Predicates, Modules, VMCodes]
  483    ].
  484stacks_stats(S) -->
  485    { get_dict(local, S, Local),
  486      get_dict(global, S, Global),
  487      get_dict(trail, S, Trail),
  488      get_dict(total, S, Total)
  489    },
  490    [ '~|~tLimit~25+~tAllocated~12+~tIn use~12+'-[], nl ],
  491    stack_stats('Local',  Local),  [nl],
  492    stack_stats('Global', Global), [nl],
  493    stack_stats('Trail',  Trail),  [nl],
  494    stack_stats('Total',  Total),  [nl].
  495
  496stack_stats('Total', S) -->
  497    { dict_human_bytes(limit,     S, Limit),
  498      dict_human_bytes(allocated, S, Allocated),
  499      dict_human_bytes(usage,     S, Usage)
  500    },
  501    !,
  502    [ '~|~tTotal:~13+~t~s~12+ ~t~s~12+ ~t~s~12+'-
  503      [Limit, Allocated, Usage]
  504    ].
  505stack_stats(Stack, S) -->
  506    { dict_human_bytes(allocated, S, Allocated),
  507      dict_human_bytes(usage,     S, Usage)
  508    },
  509    [ '~|~w ~tstack:~13+~t~w~12+ ~t~s~12+ ~t~s~12+'-
  510      [Stack, -, Allocated, Usage]
  511    ].
  512
  513dict_human_bytes(Key, Dict, String) :-
  514    get_dict(Key, Dict, Bytes),
  515    human_bytes(Bytes, String).
  516
  517human_bytes(Bytes, String) :-
  518    Bytes < 20_000,
  519    !,
  520    format(string(String), '~D  b', [Bytes]).
  521human_bytes(Bytes, String) :-
  522    Bytes < 20_000_000,
  523    !,
  524    Kb is (Bytes+512) // 1024,
  525    format(string(String), '~D Kb', [Kb]).
  526human_bytes(Bytes, String) :-
  527    Bytes < 20_000_000_000,
  528    !,
  529    Mb is (Bytes+512*1024) // (1024*1024),
  530    format(string(String), '~D Mb', [Mb]).
  531human_bytes(Bytes, String) :-
  532    Gb is (Bytes+512*1024*1024) // (1024*1024*1024),
  533    format(string(String), '~D Gb', [Gb]).
  534
  535
  536:- multifile sandbox:safe_primitive/1.  537
  538sandbox:safe_primitive(prolog_statistics:statistics(_)).
  539sandbox:safe_primitive(prolog_statistics:statistics).
  540sandbox:safe_meta_predicate(prolog_statistics:profile/1).
  541sandbox:safe_meta_predicate(prolog_statistics:profile/2)