From e29aa100962050284918a273a6e9eeb62cdeacbd Mon Sep 17 00:00:00 2001 From: wfjm Date: Tue, 30 Oct 2018 15:14:55 +0100 Subject: [PATCH] finalize performance counter support - rw11/dmpcnt.tcl: add pc_* procs to start and stop logger - dmpcntanal: added, a script to analyse logger data --- doc/CHANGELOG.md | 5 +- tools/bin/dmpcntanal | 506 ++++++++++++++++++++++++++++++++++++ tools/man/man1/dmpcntanal.1 | 282 ++++++++++++++++++++ tools/tcl/rw11/dmpcnt.tcl | 91 ++++++- 4 files changed, 880 insertions(+), 4 deletions(-) create mode 100755 tools/bin/dmpcntanal create mode 100644 tools/man/man1/dmpcntanal.1 diff --git a/doc/CHANGELOG.md b/doc/CHANGELOG.md index 19d02f1d..35a39983 100644 --- a/doc/CHANGELOG.md +++ b/doc/CHANGELOG.md @@ -44,7 +44,10 @@ The full set of tests is only run for tagged releases. - download the `ghdl` based test benches (can't be build under Travis) - execute the test benches with `tbrun` - add KW11-P support, enable it in all w11a systems -- add pdp11_dmpcnt: performance counters +- add performance counters + - pdp11_dmpcnt: an array of 32 counters of 32 bit width + - connected to 24 signals from inside pdp11_sys70 and 8 signals from outside + - dmpcntanal: analysis script ### Changes - Makefile: `make all_tcl` now quiet, use setup_packages_filt diff --git a/tools/bin/dmpcntanal b/tools/bin/dmpcntanal new file mode 100755 index 00000000..24d1b6e6 --- /dev/null +++ b/tools/bin/dmpcntanal @@ -0,0 +1,506 @@ +#!/usr/bin/perl -w +# $Id: dmpcntanal 1057 2018-10-19 15:06:42Z mueller $ +# +# Copyright 2018- by Walter F.J. Mueller +# +# This program is free software; you may redistribute and/or modify it under +# the terms of the GNU General Public License as published by the Free +# Software Foundation, either version 3, or (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, but +# WITHOUT ANY WARRANTY, without even the implied warranty of MERCHANTABILITY +# or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License +# for complete details. +# +# Revision History: +# Date Rev Version Comment +# 2018-10-19 1057 1.0 Initial version +# 2018-10-06 1053 0.1 First draft +# + +use 5.14.0; # require Perl 5.14 or higher +use strict; # require strict checking + +use Getopt::Long; +use Scalar::Util qw(looks_like_number); + +my %opts = (); + +GetOptions(\%opts, "cstate", "cevent", "clk", "cpi", "cpb", + "cache", "chit", "ibus", "rbus", + "raw=s@", "dat=s@", "fmt=s@", "sum=s@", "tot", + "cpu", "all", "hpl=i", + "help") + or die "bad options"; + +my %cnam2ind = (cpu_cpbusy => 0, + cpu_km_prix => 1, + cpu_km_pri0 => 2, + cpu_km_wait => 3, + cpu_sm => 4, + cpu_um => 5, + cpu_idec => 6, + cpu_pcload => 7, + cpu_vfetch => 8, + cpu_irupt => 9, + ca_rd => 10, + ca_wr => 11, + ca_rdhit => 12, + ca_wrhit => 13, + ca_rdmem => 14, + ca_wrmem => 15, + ca_rdwait => 16, + ca_wrwait => 17, + ib_rd => 18, + ib_wr => 19, + ib_busy => 20, + rb_rd => 21, + rb_wr => 22, + rb_busy => 23, + ext_rdrhit => 24, + ext_wrrhit => 25, + ext_wrflush => 26, + ext_rlrxact => 27, + ext_rlrxback => 28, + ext_rltxact => 29, + ext_rltxback => 20, + ext_usec => 31, + # calculated values + cpu_tot => -1, # total cpu cyles + cpu_act => -2, # active cpu cycles (no cp + wait) + ca_totwt => -3, # total cache wait cycles + ib_tot => -4, # total ibus requests + rb_tot => -5 # total rbus requests + ); + +my $sumdt = 0.4; + +my @rawnam; +my @datnam; +my @fmtdsc; +my @sumdsc; + +my %hraw; +my %hdif; + +autoflush STDOUT 1 if (-p STDOUT); # autoflush if output into pipe + +if (exists $opts{help}) { + print_help(); + exit 0; +} + +# process -raw and -dat options +foreach my $opt (@{$opts{raw}}) { push @rawnam, split /,/,$opt; } +foreach my $opt (@{$opts{dat}}) { push @datnam, split /,/,$opt; } + +# process -fmt options +foreach my $opt (@{$opts{fmt}}) { + my @olist = split /,/,$opt; + if (scalar(@olist) < 4 || scalar(@olist) > 5) { + print STDERR "dmpcntanal-E: bad -fmt option '$opt'\n"; + exit 1; + } + my $head = $olist[0]; + my $fmt = $olist[1]; + my $fac = $olist[2]; + my $namnum = $olist[3]; + my $namden = $olist[4]; + $fac = 1. unless $fac ne ''; + $fmt = '4.1' unless $fmt ne ''; + my ($fmtlen,$fmtpre) = ($fmt =~ m/^(\d)\.(\d)$/); + unless (defined $fmtlen && defined $fmtpre) { + print STDERR "dmpcntanal-E: bad format '$fmt' in -fmt\n"; + exit 1; + } + unless (length($head) <= $fmtlen) { + print STDERR "dmpcntanal-E: header '$head' longer than $fmtlen in -fmt\n"; + exit 1; + } + chknum($fac, '-fmt'); + chknam($namnum, '-fmt'); + chknam($namden, '-fmt') if defined $namden; + push @fmtdsc, {head => $head, + fmt => '%' . $fmt .'f', + fmtlen => $fmtlen, + fmtpre => $fmtpre, + fac => $fac, + namnum => $namnum, + namden => $namden + }; +} + +# process -tot option +push @{$opts{sum}}, 'total' if $opts{tot}; + +# process -sum options +foreach my $opt (@{$opts{sum}}) { + my @olist = split /,/,$opt; + if (scalar(@olist) < 1 || scalar(@olist) > 3) { + print STDERR "dmpcntanal-E: bad -sum option '$opt'\n"; + exit 1; + } else { + my $name = $olist[0]; + my $from = $olist[1]; + my $to = $olist[2]; + unless (length($name) <= 6) { + print STDERR "dmpcntanal-E: name '$name' longer than 6 in -sum\n"; + exit 1; + } + $from = 0. unless defined $from && $from ne ''; + $to = 1.e8 unless defined $to && $to ne '';; + chknum($from, '-sum'); + chknum($to, '-to'); + if ($to <= $from) { + print STDERR "dmpcntanal-E: negative time interval [$from,$to] -sum\n"; + exit 1; + } + push @sumdsc, {name => $name, + from => $from, + to => $to, + count => 0, + hdif => {} + }; + } +} + +foreach my $nam (@rawnam) { chknam($nam, '-raw') } +foreach my $nam (@datnam) { chknam($nam, '-dat') } + +# process -cache and -chit options +delete $opts{chit} if $opts{cache}; # hide -chit if -cache given + +# default to -cpu if no field specified +unless ($opts{cstate} || $opts{cevent} || + $opts{clk} || $opts{cpi} || $opts{cpb} || + $opts{cache} || $opts{chit} || $opts{ibus} || $opts{rbus} || + $opts{cpu} || $opts{all} || + scalar(@rawnam) || scalar(@datnam) || scalar(@fmtdsc)) { + $opts{cpu} = 1; +} + +# process -cpu +if ($opts{cpu}) { + $opts{cstate} = 1; + $opts{cevent} = 1; + $opts{chit} = 1; +} +# process -all +if ($opts{all}) { + $opts{cstate} = 1; + $opts{cevent} = 1; + $opts{cache} = 1; + $opts{ibus} = 1; + $opts{rbus} = 1; +} + +# and finally process data +foreach my $file (@ARGV) { + read_file($file); +} + +#------------------------------------------------------------------------------- + +sub read_file { + my ($file) = @_; + + # print headers + prthead(); + + # open file + open IFILE,"<$file" or die "failed to open $file"; + + my @vraw = (0) x 32; + my @vdif = (0) x 32; + my @vlast = (0) x 32; + my $nline = 0; + + # loop over lines in file + while () { + chomp; + next if m/^#/; + if (m/^\s*(\d+\.\d+)\s+((\s*\d+){32})$/x) { + # prepare data as array + my $time = $1; + my @vraw = split /\s+/,$2; + for (my $i=0; $i<32; $i++) { + my $dif = $vraw[$i] - $vlast[$i]; + $dif += 4.*1024.*1024.*1024. if ($dif < 0); + $vdif[$i] = $dif; + $vlast[$i] = $vraw[$i]; + } + + # prepare data as hash + foreach my $nam (keys %cnam2ind) { + next if $cnam2ind{$nam} < 0; + $hraw{$nam} = $vraw[$cnam2ind{$nam}]; + $hdif{$nam} = $vdif[$cnam2ind{$nam}]; + } + $hdif{cpu_tot} = $hdif{cpu_cpbusy} + $hdif{cpu_km_prix} + + $hdif{cpu_km_pri0} + $hdif{cpu_km_wait} + + $hdif{cpu_sm} + $hdif{cpu_um}; + $hdif{cpu_act} = $hdif{cpu_km_prix} + $hdif{cpu_km_pri0} + + $hdif{cpu_sm} + $hdif{cpu_um}; + $hdif{ca_totwt} = $hdif{ca_rdwait} + $hdif{ca_wrwait}; + $hdif{ib_tot} = $hdif{ib_rd} + $hdif{ib_wr}; + $hdif{rb_tot} = $hdif{rb_rd} + $hdif{rb_wr}; + + # accululation of (sub-)totals + foreach my $dsc (@sumdsc) { + if ($time >= $dsc->{from}-$sumdt && $time <= $dsc->{to}+$sumdt) { + $dsc->{count} += 1; + foreach my $k (keys %hdif) { $dsc->{hdif}->{$k} += $hdif{$k} } + } + } + # do printing + $nline += 1; + if ($opts{hpl} && $opts{hpl} > 0 && $nline > $opts{hpl}) { + print "\n"; + prthead(); + $nline = 0; + } + prtline(\%hraw, \%hdif, (sprintf "%6.1f", $time)); + + } else { + printf STDERR "bad line: $_\n"; + } + } + + # print (sub-)totals + if (scalar @sumdsc) { + print "\n"; + prthead(); + foreach my $dsc (@sumdsc) { + if ($dsc->{count} > 0) { + foreach my $k (keys %hdif) { $dsc->{hdif}->{$k} /= $dsc->{count} } + prtline(undef, $dsc->{hdif}, $dsc->{name}); + } else { + printf "%6s ... empty ... no data in [%4.1f,%4.1f]\n", + $dsc->{name}, $dsc->{from}-$sumdt, $dsc->{to}+$sumdt; + } + } + } + + close IFILE; + +} + + +#------------------------------------------------------------------------------- + +sub prtline { + my ($rhraw,$rhdif,$tcol) = @_; + + printf "%6s", $tcol; + if (defined $rhraw) { + foreach my $nam (@rawnam) { printf " %10.0f", $rhraw->{$nam}; } + } else { + foreach my $nam (@rawnam) { printf ' ' x 10 . '-'; } + } + foreach my $nam (@datnam) { printf " %9.0f", $rhdif->{$nam}; } + + if ($opts{cstate}) { + print ' '; + prtrat($rhdif,'%4.1f',100.,'cpu_cpbusy','cpu_tot'); + prtrat($rhdif,'%4.1f',100.,'cpu_km_prix','cpu_tot'); + prtrat($rhdif,'%4.1f',100.,'cpu_km_pri0','cpu_tot'); + prtrat($rhdif,'%4.1f',100.,'cpu_km_wait','cpu_tot'); + prtrat($rhdif,'%4.1f',100.,'cpu_sm','cpu_tot'); + prtrat($rhdif,'%4.1f',100.,'cpu_um','cpu_tot'); + } + if ($opts{clk}) { + prtval($rhdif,'%5.1f',1.e-6,'cpu_tot'); + } + if ($opts{cevent}) { + print ' '; + prtval($rhdif,'%5.2f',1.e-6,'cpu_idec'); + prtval($rhdif,'%5.0f',1.,'cpu_vfetch'); + prtval($rhdif,'%5.0f',1.,'cpu_irupt'); + prtrat($rhdif,'%4.1f',1.,'cpu_idec','cpu_pcload'); + } + if ($opts{cpi}) { + prtrat($rhdif,'%4.1f',1.,'cpu_act','cpu_idec'); + } + if ($opts{cpb}) { + prtrat($rhdif,'%4.1f',1.,'cpu_act','cpu_pcload'); + } + + if ($opts{cache}) { + print ' '; + prtrat($rhdif,'%4.2f',1.,'ca_rd','cpu_idec'); + prtrat($rhdif,'%4.2f',1.,'ca_wr','cpu_idec'); + prtrat($rhdif,'%4.1f',100.,'ca_rdhit','ca_rd'); + prtrat($rhdif,'%4.1f',100.,'ca_wrhit','ca_wr'); + prtrat($rhdif,'%4.1f',1.,'ca_rdwait','ca_rdmem'); + prtrat($rhdif,'%4.1f',1.,'ca_wrwait','ca_wrmem'); + prtrat($rhdif,'%4.1f',1.,'ca_totwt','cpu_idec'); + } + if ($opts{chit}) { + print ' '; + prtrat($rhdif,'%4.1f',100.,'ca_rdhit','ca_rd'); + prtrat($rhdif,'%4.1f',100.,'ca_wrhit','ca_wr'); + prtrat($rhdif,'%4.1f',1.,'ca_totwt','cpu_idec'); + } + + if ($opts{ibus}) { + print ' '; + prtval($rhdif,'%4.2f',1.e-3,'ib_rd'); + prtval($rhdif,'%4.2f',1.e-3,'ib_wr'); + prtrat($rhdif,'%4.1f',1.,'ib_busy','ib_tot'); + } + if ($opts{rbus}) { + print ' '; + prtval($rhdif,'%4.2f',1.e-3,'rb_rd'); + prtval($rhdif,'%4.2f',1.e-3,'rb_wr'); + prtrat($rhdif,'%4.1f',1.,'rb_busy','rb_tot'); + } + + foreach my $dsc (@fmtdsc) { + if (defined $dsc->{namden}) { + prtrat($rhdif, $dsc->{fmt}, $dsc->{fac}, $dsc->{namnum}, $dsc->{namden}); + } else { + prtval($rhdif, $dsc->{fmt}, $dsc->{fac}, $dsc->{namnum}); + } + } + printf "\n"; +} + +#------------------------------------------------------------------------------- + +sub prthead { + # print header line 1 + printf ' time'; + foreach my $nam (@rawnam) { printf " %9s_", (split /_/,$nam,2)[0]; } + foreach my $nam (@datnam) { printf " %8s_", (split /_/,$nam,2)[0];} + print ' ------ cpu state in % -------' if $opts{cstate}; + print ' clock' if $opts{clk}; + print ' ----- cpu events -----' if $opts{cevent}; + print ' ----' if $opts{cpi}; + print ' ----' if $opts{cpb}; + print ' -------------- cache -------------' if $opts{cache}; + print ' ---- cache ---' if $opts{chit}; + print ' ---- ibus ----' if $opts{ibus}; + print ' ---- rbus ----' if $opts{rbus}; + my $fmtcol = 0; + foreach my $dsc (@fmtdsc) { $fmtcol += $dsc->{fmtlen}+1 } + if ($fmtcol > 0) { + my $ndash = $fmtcol - 6; + my $nleft = int($ndash/2); + my $nright = $ndash - $nleft; + print ' ' . '-'x$nleft . ' fmt ' . '-'x$nright; + } + printf "\n"; + + # print header line 2 + printf " sec"; + foreach my $nam (@rawnam) { printf " %10s", (split /_/,$nam,2)[1]; } + foreach my $nam (@datnam) { printf " %9s", (split /_/,$nam,2)[1]; } + print ' cp km>0 km=0 wait sm um' if $opts{cstate}; + print ' MHz' if $opts{clk}; + print ' Min/s vfetc irupt i/b' if $opts{cevent}; + print ' c/i' if $opts{cpi}; + print ' c/b' if $opts{cpb}; + print ' r/i w/i rhit whit rwt wwt wt/i' if $opts{cache}; + print ' rhit whit wt/i' if $opts{chit}; + print ' rdkH wrkH wt/r' if $opts{ibus}; + print ' rdkH wrkH wt/r' if $opts{rbus}; + foreach my $dsc (@fmtdsc) { printf " %$dsc->{fmtlen}s", $dsc->{head}} + printf "\n"; +} + +#------------------------------------------------------------------------------- + +sub prtrat { + my ($rhdif,$fmt,$mul,$namnum,$namden) = @_; + if (not exists $rhdif->{$namnum} || not exists $rhdif->{$namden}) { + prtbad($fmt); + } else { + my $rat = 0.; + $rat = $rhdif->{$namnum} / $rhdif->{$namden} if $rhdif->{$namden} > 0.; + prtfmt($fmt, $rat*$mul); + } +} + +#------------------------------------------------------------------------------- + +sub prtval { + my ($rhdif,$fmt,$mul,$nam) = @_; + if (not exists $rhdif->{$nam}) { + prtbad($fmt); + } else { + prtfmt($fmt, $rhdif->{$nam}*$mul); + } +} + +#------------------------------------------------------------------------------- + +sub prtfmt { + my ($fmt,$val) = @_; + my ($len,$prec) = ($fmt =~ m/(\d)\.(\d)/); + my $str = sprintf $fmt, $val; + if (($prec == 0 && length($str) > $len) || + ($prec > 0 && length($str) > $len+$prec+1)) { + print ' ' . '*' x $len; + return + } + $str = substr($str,0,$len) if length($str) > $len; + print ' ' . $str; +} + +#------------------------------------------------------------------------------- + +sub prtbad { + my ($fmt) = @_; + my ($len,$prec) = ($fmt =~ m/(\d)\.(\d)/); + print ' ' x $len . '-'; +} + +#------------------------------------------------------------------------------- + +sub chknam { + my ($nam,$cmd) = @_; + return if exists $cnam2ind{$nam}; + print STDERR "dmpcntanal-E: unknown counter name '$nam' in $cmd\n"; + exit 1; +} + +#------------------------------------------------------------------------------- + +sub chknum { + my ($num,$cmd) = @_; + return if looks_like_number($num); + print STDERR "dmpcntanal-E: bad factor '$num' in $cmd\n"; + exit 1; +} + +#------------------------------------------------------------------------------- + +sub print_help { + print "usage: dmpcntanal file\n"; + print " --cstate show cpu state colums\n"; + print " --cevent show cpu events colums\n"; + print " --clk show cpu clock column\n"; + print " --cpi show cpu cycle/instruction column\n"; + print " --cpb show cpu cycle/branch column\n"; + print " --cache show all cache colums\n"; + print " --chit show cache hit+wait colums (subset of --cache)\n"; + print " --ibus show ibus colums\n"; + print " --rbus show rbus colums\n"; + print " --raw=c[,c,..] show raw data of counter c\n"; + print " --dat=c[,c,..] show rate data of counter c\n"; + print " --fmt=h,f,m,n[,d] add custom colum with\n"; + print " h header text\n"; + print " f format as len.pre (default 4.1)\n"; + print " m multiplier (default 1.)\n"; + print " n numerator counter name\n"; + print " d denominator counter name (optional)\n"; + print " --sum=n[,f[,t]] add sub-total line, with\n"; + print " n name printed in time column\n"; + print " f from, begin of interval (optional)\n"; + print " t to, end of interval (optional)\n"; + print " --tot add total line (short for -sum=total)\n"; + print " --cpu short for -cstate -cevent -chit (default view)\n"; + print " --all short for -cstate -cevent -cache -ibus -rbus\n"; + print " --hpl=n print header after n lines\n"; + print " --help this message\n"; +} diff --git a/tools/man/man1/dmpcntanal.1 b/tools/man/man1/dmpcntanal.1 new file mode 100644 index 00000000..61b5ebc9 --- /dev/null +++ b/tools/man/man1/dmpcntanal.1 @@ -0,0 +1,282 @@ +.\" -*- nroff -*- +.\" $Id: dmpcntanal.1 1059 2018-10-27 10:34:16Z mueller $ +.\" +.\" Copyright 2018- by Walter F.J. Mueller +.\" +.\" ------------------------------------------------------------------ +. +.TH DMPCNTANAL 1 2018-10-21 "Retro Project" "Retro Project Manual" +.\" ------------------------------------------------------------------ +.SH NAME +dmpcntanal \- analyze dmpcnt data +.\" ------------------------------------------------------------------ +.SH SYNOPSIS +. +.SY dmpcntanal +.RI [ OPTION ]... +.I FILE +. +.SY dmpcntanal +.B \-\-help +.YS +. +.\" ------------------------------------------------------------------ +.SH DESCRIPTION +Reads a list of CPU performance counter raw data, usually generated via +a \fIrw11::pc_lsta\fR command, and generates human readable reports. +. +.\" ------------------------------------------------------------------ +.SH OPTIONS +. +.\" ---------------------------------------------- +.IP "\fB\-\-cstate\fR" +show the CPU state columns, which give in percent the fraction of +clock cycles spend in different CPU states: +.RS +.IP \fIcp\fP +console port handling, mostly rbus processing. +.PD 0 +.IP \fIkm>0\fP +kernel mode at priority > 0, interrupt handling or interrupt lock-out +.IP \fIkm=0\fP +kernel mode at priority == 0 +.IP \fIwait\fP +idling in a WAIT instruction +.IP \fIsm\fP +supervisor mode +.IP \fIsum\fP +user mode +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-cevents\fR" +show the CPU events columns +.RS +.IP \fIMin/s\fP +instruction rate in MHz +.PD 0 +.IP \fIvfetc\fP +vector fetch rate, sum of traps, exceptions and interrupts. +.IP \fIirupt\fP +interrupt rate +.IP \fIi/b\fP +instruction per branch +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-clk\fR" +clock rate on MHz, counting only cycles when CPU running. In normal +operation this is equivalent to the system clock rate. +. +.\" ---------------------------------------------- +.IP "\fB\-\-cpi\fR" +show the CPU cycle/instruction column. +. +.\" ---------------------------------------------- +.IP "\fB\-\-cpb\fR" +show the CPU cycle/branch column. +. +.\" ---------------------------------------------- +.IP "\fB\-\-cache\fR" +show all cache columns. +.RS +.IP \fIr/i\fP +number of read requests per instruction. +.PD 0 +.IP \fIw/i\fP +number of write requests per instruction. +.IP \fIrhit\fP +read hit rate in %. +.IP \fIwhit\fP +write hit rate in %. +.IP \fIrwt\fP +average number of wait cycles per memory read (in miss case). +.IP \fIwwt\fP +average number of wait cycles per memory write (from back pressure). +.IP \fIwt/i\fP +average number of memory wait cycles per instruction. +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-chit\fR" +show cache columns \fIrhit\fP, \fIwhit\fP and \fIwt/i\fP, subset of +\fB--cache\fR. +. +.\" ---------------------------------------------- +.IP "\fB\-\-ibus\fR" +show all ibus columns. +.RS +.IP \fIrdkH\fP +ibus read rate in kHz. +.PD 0 +.IP \fIwrkH\fP +ibus write rate in kHz. +.IP \fIwt/r\fP +average number of ibus wait cycles (read and write combined). +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-rbus\fR" +show all rbus columns. +.RS +.IP \fIrdkH\fP +ibus read rate in kHz. +.PD 0 +.IP \fIwrkH\fP +ibus write rate in kHz. +.IP \fIwt/r\fP +average number of ibus wait cycles (read and write combined). +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-raw\fR=\fIclist\fR" +show raw data of the counters given in the comma separated list of +counter names \fIclist\fR. +. +.\" ---------------------------------------------- +.IP "\fB\-\-dat\fR=\fIclist\fR" +show data rate of the counters given in the comma separated list of +counter names \fIclist\fR. +. +.\" ---------------------------------------------- +.IP "\fB\-\-fmt\fR=\fIhdr,[fmt],[mul],num[,den]\fR" +add custom column with a scaled counter rate or a scaled counter ratio +specified with +.RS +.IP \fBhdr\fP +text for header. The length if the header must be equal or less than the +width of the format. +.PD 0 +.IP \fBfmt\fP +format in the form like \fIw.p\fR with a single digit field width \fIw\fR +and single digit precision \fIp\fR. If \fIp\fR is \fI0\fR no decimal point +is printed. If omitted \fI4.1\fR is assumed. +.IP \fBmul\fP +multiplier, given as integer of floating point number. +If omitted 1. is assumed. +.IP \fBnum\fP +name of numerator counter +.IP \fBden\fP +name of denominator counter. If specified the ratio \fInum/den\fR is +printed, if omitted the rate \fInum\fR is printed. +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-sum\fR=\fInam[,from[,to]]\fR" +allows to determine averages for a given time interval with +.RS +.IP \fBnam\fP +name printed in the 1st column, up to 6 characters allowed. +.PD 0 +.IP \fBfrom\fP +start time of averaging, if omitted start at begin. +.IP \fBto\fP +end time of averaging, if omitted sum to the end. +.PD +.RE +. +.\" ---------------------------------------------- +.IP "\fB\-\-tot\fR" +add line with average values for the whole dataset, short for \fB-sum=total\fR. +. +.\" ---------------------------------------------- +.IP "\fB\-\-cpu\fR" +short for \fB-cstate -cevent -chit\fR. If no option which generates +an output column is given and a \fB\-cpu\fR style output is generated. +. +.\" ---------------------------------------------- +.IP "\fB\-\-all\fR" +short for \fB-cstate -cevent -cache -ibus -rbus\fR. +. +.\" ---------------------------------------------- +.IP "\fB\-\-hpl\fR=\fIn\fR" +print header after \fIn\fR lines. +. +.\" ---------------------------------------------- +.IP "\fB\-\-help\fR" +print full help text and exit. +. +.\" ------------------------------------------------------------------ +.SH COLUMN DEFINITIONS +All standard columns generated via options like \fB-cstate\fR can +also be created via the \fB-fmt\fR option with the following parameters +.EX + + name format mul numerator denominator + + cp 4.1 100. cpu_cpbusy cpu_tot + km>0 4.1 100. cpu_km_prix cpu_tot + km=0 4.1 100. cpu_km_pri0 cpu_tot + wait 4.1 100. cpu_km_wait cpu_tot + sm 4.1 100. cpu_sm cpu_tot + um 4.1 100. cpu_um cpu_tot + + Min/s 5.2 1.e-6 cpu_idec + vfetch 5.0 1. cpu_vfetch + irupt 5.0 1. cpu_irupt + i/b 4.1 1. cpu_idec cpu_pcload + + r/i 4.2 1. ca_rd cpu_idec + w/i 4.2 1. ca_wr cpu_idec + rhit 4.1 100. ca_rdhit ca_rd + whit 4.1 100. ca_wrhit ca_wr + rwt 4.1 1. ca_rdwait ca_rdmem + wwt 4.1 1. ca_wrwait ca_wrmem + wt/i 4.1 1. ca_totwt cpu_idec + + rdkH 4.2 1.e-3 ib_rd + wrkH 4.2 1.e-3 ib_wr + wt/r 4.1 1. ib_busy ib_tot + + rdkH 4.2 1.e-3 rb_rd + wrkH 4.2 1.e-3 rb_wr + wt/r 4.1 1. rb_busy rb_tot +.EE + +.\" ------------------------------------------------------------------ +.SH EXAMPLES +.IP "\fBdmpcntanal -cstate -cevent -tot pc_dmpcnt_xxx.dat\fR" 4 +reads the file \fIpc_dmpcnt_xxx.dat\fR and generates a report with the +\fB-cstate\fR and \fB-cevent\fR columns sets. + +The input file is typically generated by a \fBti_w11\fR tcl command like + +.EX + rw11::pc_clear + rw11::pc_start + rw11::pc_lsta pc_dmpcnt_xxx.dat +.EE + +The output might look like + +.EX + time ------ cpu state in % ------- ----- cpu events ----- + sec cp km>0 km=0 wait sm um Min/s vfetc irupt i/b + ... + 38.0 0.7 10.4 19.2 4.0 0.0 65.7 8.95 1319 712 4.2 + 39.0 0.4 5.1 9.9 1.4 0.0 83.1 9.76 1021 373 4.0 + 40.0 0.7 9.4 18.6 3.6 0.0 67.8 8.60 1135 616 4.5 + 41.0 0.4 4.6 9.5 1.1 0.0 84.4 9.81 1190 313 4.1 + 42.0 0.6 7.1 18.0 3.4 0.0 70.8 9.33 1153 611 3.9 + 43.0 0.5 7.6 15.0 4.1 0.0 72.7 9.15 1278 540 4.1 + 44.0 0.6 9.2 15.8 3.0 0.0 71.4 8.87 1267 509 4.4 + 45.0 0.6 7.4 16.7 3.2 0.0 72.1 8.96 1276 552 4.2 + ... + time ------ cpu state in % ------- ----- cpu events ----- + sec cp km>0 km=0 wait sm um Min/s vfetc irupt i/b + total 0.5 7.0 17.0 19.7 0.0 55.8 7.28 1453 471 3.9 +.EE + +.\" ------------------------------------------------------------------ +.SH "SEE ALSO" +.BR ti_w11 (1) + +.\" ------------------------------------------------------------------ +.SH AUTHOR +Walter F.J. Mueller diff --git a/tools/tcl/rw11/dmpcnt.tcl b/tools/tcl/rw11/dmpcnt.tcl index e7058335..c56c0adc 100644 --- a/tools/tcl/rw11/dmpcnt.tcl +++ b/tools/tcl/rw11/dmpcnt.tcl @@ -1,4 +1,4 @@ -# $Id: dmpcnt.tcl 1056 2018-10-13 16:01:17Z mueller $ +# $Id: dmpcnt.tcl 1058 2018-10-21 21:46:26Z mueller $ # # Copyright 2018- by Walter F.J. Mueller # @@ -13,6 +13,7 @@ # # Revision History: # Date Rev Version Comment +# 2018-10-21 1058 1.1 add logger, pc_l* commands # 2018-10-13 1055 1.0 Initial version # 2018-09-23 1050 0.1 First draft # @@ -30,7 +31,7 @@ namespace eval rw11 { {func 2 3 "s:NOOP:NOOP1:NOOP2:NOOP3:STO:STA:CLR:LOA"} regdsc PC_STAT {ainc 15} {caddr 13 5} {waddr 8} {run 0} - # preliminary handling of counter names, hack in first version + # preliminary handling of counter names, hack in first version variable pcnt_cnames [list cpu_cpbusy cpu_km_prix cpu_km_pri0 cpu_km_wait \ cpu_sm cpu_um cpu_idec cpu_pcload \ cpu_vfetch cpu_irupt ca_rd ca_wr \ @@ -46,7 +47,12 @@ namespace eval rw11 { incr tmp_ind } unset tmp_ind - + + variable pcnt_timesta 0 + variable pcnt_timenext 0 + variable pcnt_logaftid 0 + variable pcnt_logchan 0 + # # pc_setup: rmap definitions for dmpcnt # @@ -126,5 +132,84 @@ namespace eval rw11 { } return $rval } + + # + # pc_lsta: start logging + # + proc pc_lsta {{file ""}} { + variable pcnt_timesta + variable pcnt_timenext + variable pcnt_logaftid + variable pcnt_logchan + + if {$pcnt_logchan != 0} { error "pc logger already running" } + + if {$file eq ""} { + set timestamp [clock format [clock seconds] -format "%Y-%m-%d-%H%M%S"] + set file "pc_dmpcnt$timestamp.dat" + } + + pc_clear + pc_start + + set pcnt_logchan [open $file w] + fconfigure $pcnt_logchan -buffering line + set pcnt_timesta [clock milliseconds] + set pcnt_timenext $pcnt_timesta + after 0 rw11::pc_lhdl + return "" + } + + # + # pc_lsto: stop logging + # + proc pc_lsto {} { + variable pcnt_logaftid + variable pcnt_logchan + variable pcnt_timesta + variable pcnt_timenext + + if {$pcnt_logchan == 0} { return "" } + + after cancel $pcnt_logaftid + close $pcnt_logchan + set pcnt_logchan 0 + set pcnt_timesta 0 + set pcnt_timenext 0 + set pcnt_logaftid 0 + return "" + } + + # + # pc_lcom: add comment to logger + # + proc pc_lcom {{comment ""}} { + variable pcnt_logchan + if {$pcnt_logchan == 0} { error "pc logger not running" } + puts $pcnt_logchan "# $comment" + return "" + } + + # + # pc_lhdl: logger handler + # + proc pc_lhdl {} { + variable pcnt_timesta + variable pcnt_timenext + variable pcnt_logaftid + variable pcnt_logchan + if {$pcnt_logchan == 0} { return "" } + set tela [expr {([clock milliseconds]-$pcnt_timesta)/1000.}] + set pclist [pc_read] + set line [format "%10.3f " $tela] + foreach {pc} $pclist { + append line [format " %1.0f" $pc] + } + puts $pcnt_logchan $line + set pcnt_timenext [expr {$pcnt_timenext + 1000}] + set dt [expr { $pcnt_timenext - [clock milliseconds]}] + after $dt rw11::pc_lhdl + return "" + } }