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. --- --- 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 --- --- 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 --- --- 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. SEE ALSO ======== * getrusage(2) getrusage(3p) 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 */ }; * timeval (3bsd) 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.