Help language development. Donate to The Perl Foundation

ProcStats cpan:LEMBARK last updated on 2020-01-24

ProcStats-0.3.0/

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.

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

Exported with :Extract.

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".

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

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.

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.

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

NOTES

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.

SEE ALSO

getrusage is POSIX (3p).

Thing is that Linux does not maintain values for all of the contents (see getrusage(2) for descriptions).

struct rusage
{
   struct timeval ru_utime; /* user CPU time used */
   struct timeval ru_stime; /* system CPU time used */
   long   ru_maxrss;        /* maximum resident set size */
 * long   ru_ixrss;         /* integral shared memory size */
 * long   ru_idrss;         /* integral unshared data size */
 * long   ru_isrss;         /* integral unshared stack size */
   long   ru_minflt;        /* page reclaims (soft page faults) */
   long   ru_majflt;        /* page faults (hard page faults) */
 * long   ru_nswap;         /* swaps */
   long   ru_inblock;       /* block input operations */
   long   ru_oublock;       /* block output operations */
 * long   ru_msgsnd;        /* IPC messages sent */
 * long   ru_msgrcv;        /* IPC messages received */
 * long   ru_nsignals;      /* signals received */
   long   ru_nvcsw;         /* voluntary context switches */
   long   ru_nivcsw;        /* involuntary context switches */
};

Struct timeval is a pair of ints for seconds + microseconds which are dealt with by dividing the microseconcs and adding to get utime and stime in the reported stats.