NAME

ProcStats - dump rusage process statistics with optional label.

SYNOPSIS

# display process stats provided by 
# getrusage(2) & now() to stderr ($*ERR).
#
# Initial stats show all values as-is with an 
# added "initial" and $*INIT-INSTANT. 
# 
# Successive calls print progressive stats
# for non-zero incremental differences with
# leading '+' to indicate differences.
#
# Final includes all values with totals from
# initial values and include a "Final" key
# with value of elapsed time from the program
# startup to the final sample.
#
# outputs are YAML array-of-hashes, with one
# document per print.
#
# see example/bare-for-loop

#!/usr/bin/env perl6
use v6.d;
use ProcStats;  # or ( :Print ) for print-stats.

print-stats :label( $*PROGRAM );

print-stats
for 1 .. 3;

print-stats( final => True );

# output #0 has all parameters without any differences
# (there is no prior sample to diff).
# successive stats w/o prior will show only outputs with
# differenes in stats other than user and wallclock time
# using a leading '+' for the offset values.
#
# if 'final' is used then all stats are output, even if
# they are zero, and Final => True is added to the output.
# (:final defaults to :first, :force).
#
# label is output if provided (e.g., :label($*PROGRAM) );

---
label    : ./bare-for-loop
output   : 0
sample   : 0
initial  : 1563047524.012407    # $*INIT-INSTANT
wtime    : 1563047524.627299    # now()
utime    : 0.269591
stime    : 0.038513
maxrss   : 105852
minflt   : 20822
majflt   : 0
inblock  : 0
oublock  : 8
---
output   : 1
sample   : 1
maxrss   : +760         # only stats with differnces
minflt   : +173         # are listed.
utime    : +0.018007    # utime and wtime will always grow,
wtime    : +0.008687    # returned with :force or other diff's.
---
<snip...>
---
output   : 4            # 4 == 4 => all samples were output
sample   : 4
inblock  : +0           # +0 => no change during execution
majflt   : +0
maxrss   : +1024        # >0 => growth compared to sample0
minflt   : +247         
oublock  : +0
stime    : +0.000745    # system time during samples.
utime    : +0.038095    # user time during samples.
wtime    : +0.019526    # elapsed wallclock from sample0
final    : +0.804102    # elapsed wallclock from program init.

# Output is only provided if there are differences in
# the compared fields. If any of those are different
# then the wallclock, user, and system times are added
# the entire difference returned.
#
# :force & :first can be used with intermediate
# outputs to generate output for all fields or compute
# differenes with first sample.
#
# :final(True) defaults :force and :first to true.

print-stats :force;         # ouput zeros.
print-stats :first;         # compare to sample0.

print-stats :first :force;  # all stats compared to sample0.

# see example/rand-user-table

print-stats label => "$*PROGRAM";

for 1 .. 100
{
    (
        &user-add  => 0.10,
        &user-drop => 0.10,
        &user-op   => 0.80,
    ).Mix.roll( 1_000 )».()
    ;

    print-stats label => 'Keys: ' ~ %user-data.elems;
}

print-stats :final, label => 'Keys: ' ~ %user-data.elems;

# output

---
label    : exmaple/rand-user-table
output   : 0                        # first sample:
sample   : 0                        # output = sample = 0.
wtime    : 1563048388.1687117
utime    : 0.579475
stime    : 0
maxrss   : 116448
minflt   : 23573
majflt   : 0
inblock  : 0
oublock  : 8
---
label    : Keys: 19
output   : 1
sample   : 1
maxrss   : +3884
minflt   : +901
utime    : +0.100587
wtime    : +0.052823
---
<snip...>
---
label    : Keys: 60
output   : 14           # 1 .. 14 output have 1 .. 14
sample   : 14           # samples: something changed each time.
maxrss   : +264
minflt   : +24
utime    : +0.029787    # utime & wtime are alwyas output if
wtime    : +0.020622    # there are other differences.
---
label    : Keys: 117
output   : 15           # 15th output has 18th sample:
sample   : 18           # samples 15 .. 17 were unchanged.
minflt   : +27          # minflt increased 27 in sample 18.
utime    : +0.027277
wtime    : +0.022936
---
<snip...>

---
label    : Keys: 129
output   : 61           # 39 samples had no differences
sample   : 100
minflt   : +10          # minflt increased by 10.
utime    : +0.024304
wtime    : +0.024276
---
label    : Keys: 129
output   : 62           # 62 changes.
sample   : 101          # in 101 samples.
inblock  : +0           # +0 values never changed.
majflt   : +0
maxrss   : +9424
minflt   : +2323
oublock  : +0
stime    : +0
utime    : +2.361321
wtime    : +2.202044    # elapsed wallclock from first call.
final    : +0.804102    # sec from initial -> final wtime.

DESCRIPTION

This module exports print-stats (via DEFAULT or :Print) or extract-stats & diff-stats (via :Extract). Together these give a simple interface for accessing process statistics via getrusage(2) on systems which support it.

Subroutines

Exported by default or with :Print.

print-stats

Formats the result of calling diff-stats on extract-stats, passing through :force & :final.

Exported with :Extract.

extract-stats

Calls getrusage(2), removes the parameters not supported by Linux (see Procstats::IGNORE). getrusage returns user and system times as separate int's for seconds and microseconds. These are removed from the initial input, combined into a rational, and rounded to microseconds as "stime" & "utime". Additionally now() is rounded to microseconds and returned as "wtime".

diff-stats

If :force is used then all non-ignored values are compared; if :first is used then differnces are compared with the initial sample not the prior one.

Note that :force & :first have no effect on the initial sample.

Normally compared incrmental keys are:

stime
maxrss
minflt majflt  
inblock oublock

If at least one of these does not provide non-zero differences then nothing is printed. Using ":force" will cause diff-stats to always generate a list of differences and will always yield

Notes

Sample & Output

Comparing sample & output counts allows verifying average rate at which parameters change: output only increments when something changes, %sample increments with every call to extract-stats.

Wallclock Time (wtime)

This is derived from Perl's now() result (rounded to microseconds). Combined with the program name ($*PROGRAM), this makes a reasonable candiate key for tracking execution history over mulitple tests.

Sample code.

rand-user-table

This performs a set of random operations on a hash by adding keys, dropping keys, and incrementing the stored values.

It prints the stats every 1000 iterations of the trial:

for 1 .. 1000
{
    constant weighted_operations =
    (
        &user-add  => 0.10,
        &user-drop => 0.10,
        &user-op   => 0.80,
    ).Mix;

    weighted_operations.roll( 1_000 )».();

    print-stats label => 'Keys: ' ~ %user-data.elems;
}

The output illustrates adding progress information to the labels, and will [usually] show examples of the output count being lower than the sample count due to the compared statistics not changing.

Also note here that the final sample shows wallclock time less than user time: MOAR is threaded! Use wtime for elapsed:

stime will grow due to output from print-stats and overhead from calling getrusage(2). Where stime is very small it is probably due to overhead from ProcStats.

---
label    : Keys: 13

Final : True output : 53 sample : 101 inblock : +0 majflt : +0 maxrss : +5768 minflt : +1467 oublock : +0 stime : +0.018914 utime : +2.24491 # 2.24 > 2.12 due to threading! wtime : +2.123665

NOTES

Linux-specific

This could easily be split into extract-stats with O/S-specific extractors and a top module with diff-stats and print-stats. If anyone has access to BSD, Windows, VMS, or OSX systems with Perl6 feel free to send me the information on how to extract the stats and I'll break this up into platform-specific extractors and the rest.