package CHI::Stats; $CHI::Stats::VERSION = '0.61'; use CHI::Util qw(json_encode json_decode); use List::Util qw(sum); use Log::Any qw($log); use Moo; use strict; use warnings; has 'chi_root_class' => ( is => 'ro' ); has 'data' => ( is => 'ro', default => sub { {} } ); has 'enabled' => ( is => 'rwp', default => sub { 0 } ); has 'start_time' => ( is => 'ro', default => sub { time } ); sub enable { $_[0]->_set_enabled(1) } sub disable { $_[0]->_set_enabled(0) } sub flush { my ($self) = @_; my $data = $self->data; foreach my $label ( sort keys %$data ) { my $label_stats = $data->{$label}; foreach my $namespace ( sort keys(%$label_stats) ) { my $namespace_stats = $label_stats->{$namespace}; if (%$namespace_stats) { $self->log_namespace_stats( $label, $namespace, $namespace_stats ); } } } $self->clear(); } sub log_namespace_stats { my ( $self, $label, $namespace, $namespace_stats ) = @_; my %data = ( label => $label, end_time => time(), namespace => $namespace, root_class => $self->chi_root_class, %$namespace_stats ); %data = map { /_ms$/ ? ( $_, int( $data{$_} ) ) : ( $_, $data{$_} ) } keys(%data); $log->infof( 'CHI stats: %s', json_encode( \%data ) ); } sub format_time { my ($time) = @_; my ( $sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst ) = localtime($time); return sprintf( "%04d%02d%02d:%02d:%02d:%02d", $year + 1900, $mon + 1, $mday, $hour, $min, $sec ); } sub stats_for_driver { my ( $self, $cache ) = @_; my $stats = ( $self->data->{ $cache->label }->{ $cache->namespace } ||= {} ); $stats->{start_time} ||= time; return $stats; } sub parse_stats_logs { my $self = shift; my ( %results_hash, @results, %numeric_fields_seen ); foreach my $log_file (@_) { my $logfh; if ( ref($log_file) ) { $logfh = $log_file; } else { open( $logfh, '<', $log_file ) or die "cannot open $log_file: $!"; $log->infof( "processing '%s'", $log_file ); } while ( my $line = <$logfh> ) { chomp($line); if ( my ($json) = ( $line =~ /CHI stats: (\{.*\})$/ ) ) { my %hash = %{ json_decode($json) }; my $root_class = delete( $hash{root_class} ); my $namespace = delete( $hash{namespace} ); my $label = delete( $hash{label} ); my $results_set = ( $results_hash{$root_class}->{$label}->{$namespace} ||= {} ); if ( !%$results_set ) { $results_set->{root_class} = $root_class; $results_set->{namespace} = $namespace; $results_set->{label} = $label; push( @results, $results_set ); } while ( my ( $key, $value ) = each(%hash) ) { next if $key =~ /_time$/; $results_set->{$key} += $value; $numeric_fields_seen{$key}++; } } } } my @numeric_fields = sort( keys(%numeric_fields_seen) ); my $sum = sub { my ( $rs, $name, @fields ) = @_; if ( grep { $rs->{$_} } @fields ) { $rs->{$name} = sum( map { $rs->{$_} || 0 } @fields ); } }; foreach my $rs (@results) { $sum->( $rs, 'misses', 'absent_misses', 'expired_misses' ); $sum->( $rs, 'gets', 'hits', 'misses' ); } my %totals = map { ( $_, 'TOTALS' ) } qw(root_class namespace label); foreach my $field (@numeric_fields) { $totals{$field} = sum( map { $_->{$field} || 0 } @results ); } push( @results, \%totals ); my $divide = sub { my ( $rs, $name, $top, $bottom ) = @_; if ( $rs->{$top} && $rs->{$bottom} ) { $rs->{$name} = ( $rs->{$top} / $rs->{$bottom} ); } }; foreach my $rs (@results) { $divide->( $rs, 'avg_compute_time_ms', 'compute_time_ms', 'computes' ); $divide->( $rs, 'avg_get_time_ms', 'get_time_ms', 'gets' ); $divide->( $rs, 'avg_set_time_ms', 'set_time_ms', 'sets' ); $divide->( $rs, 'avg_set_key_size', 'set_key_size', 'sets' ); $divide->( $rs, 'avg_set_value_size', 'set_value_size', 'sets' ); $divide->( $rs, 'hit_rate', 'hits', 'gets' ); } return \@results; } sub clear { my ($self) = @_; my $data = $self->data; foreach my $key ( keys %{$data} ) { %{ $data->{$key} } = (); } $self->{start_time} = time; } 1; __END__ =pod =head1 NAME CHI::Stats - Record and report per-namespace cache statistics =head1 VERSION version 0.61 =head1 SYNOPSIS # Turn on statistics collection CHI->stats->enable(); # Perform cache operations # Flush statistics to logs CHI->stats->flush(); ... # Parse logged statistics my $results = CHI->stats->parse_stats_logs($file1, ...); =head1 DESCRIPTION CHI can record statistics, such as number of hits, misses and sets, on a per-namespace basis and log the results to your L logger. You can then parse the logs to get a combined summary. A single CHI::Stats object is maintained for each CHI root class, and tallies statistics over any number of CHI::Driver objects. Statistics are reported when you call the L method. You can choose to do this once at process end, or on a periodic basis. =head1 METHODS =over =item enable, disable, enabled Enable, disable, and query the current enabled status. When stats are enabled, each new cache object will collect statistics. Enabling and disabling does not affect existing cache objects. e.g. my $cache1 = CHI->new(...); CHI->stats->enable(); # $cache1 will not collect statistics my $cache2 = CHI->new(...); CHI->stats->disable(); # $cache2 will continue to collect statistics =item flush Log all statistics to L (at Info level in the CHI::Stats category), then clear statistics from memory. There is one log message for each distinct triplet of L, L, and L. Each log message contains the string "CHI stats:" followed by a JSON encoded hash of statistics. e.g. CHI stats: {"absent_misses":1,"label":"File","end_time":1338410398, "get_time_ms":5,"namespace":"Foo","root_class":"CHI", "set_key_size":6,"set_time_ms":23,"set_value_size":20,"sets":1, "start_time":1338409391} =item parse_stats_logs Accepts one or more stats log files as parameters. Parses the logs and returns a listref of stats hashes by root class, cache label, and namespace. e.g. [ { root_class => 'CHI', label => 'File', namespace => 'Foo', absent_misses => 100, avg_compute_time_ms => 23, ... }, { root_class => 'CHI', label => 'File', namespace => 'Bar', ... }, ] Lines with the same root class, cache label, and namespace are summed together. Non-stats lines are ignored. The parser will ignore anything on the line before the "CHI stats:" string, e.g. a timestamp. Each parameter to this method may be a filename or a reference to an open filehandle. =back =head1 STATISTICS The following statistics are tracked in the logs: =over =item * C - Number of gets that failed due to item not being in the cache =item * C - Total time spent computing missed results in L, in ms (divide by number of computes to get average). i.e. the amount of time spent in the code reference passed as the third argument to compute(). =item * C - Number of L calls =item * C - Number of gets that failed due to item expiring =item * C - Number of caught runtime errors during gets =item * C - Total time spent in get operation, in ms (divide by number of gets to get average) =item * C - Number of gets that succeeded =item * C - Number of bytes in set keys (divide by number of sets to get average) =item * C - Number of bytes in set values (divide by number of sets to get average) =item * C - Total time spent in set operation, in ms (divide by number of sets to get average) =item * C - Number of sets =item * C - Number of caught runtime errors during sets =back The following additional derived/aggregate statistics are computed by L: =over =item * C - C + C =item * C - C + C =item * C - C / C =item * C - C / C =item * C - C / C =item * C - C / C =item * C - C / C =item * C - C / C =back =head1 SEE ALSO L =head1 AUTHOR Jonathan Swartz =head1 COPYRIGHT AND LICENSE This software is copyright (c) 2021 by Jonathan Swartz. This is free software; you can redistribute it and/or modify it under the same terms as the Perl 5 programming language system itself. =cut