Gitlab Community Edition Instance

Commit 9e648ae6 authored by bnachtw's avatar bnachtw
Browse files

Merge branch 'newprofiling' into 'master'

Newprofiling

See merge request !1
parents 6566c879 43c5ea6e
......@@ -66,6 +66,7 @@
# 2020-02-12 0.6.8.1 add trailing "*" to backup path for windows again
# 2021-07-14 0.6.8.2 changed names of log files, adding "dsmci"
# 2021-07-15 0.6.9 identify and remove duplicate entries with "SUN" and "SUY" keeping "SUN" if both are given
# 2021-11-29 0.6.10 move evaluation for profiling to child tread, collect more detailed data
#
# important notes
#
......@@ -73,7 +74,7 @@
#
##############################################################################
my $debugmode = 0; # 1 equals TRUE, enabels some printf debugging and prevents removing logfiles
my $debugmode = 0; # >1 equals TRUE, enabels some printf debugging and prevents removing logfiles
##############################################################################
##############################################################################
# global settings / global variables
......@@ -116,30 +117,28 @@ use constant RETURNPIDFOUND => 15; # stopped due to existing pid file
use constant RETURNNOTHREAD => 21; # cannot start new threads
my $date; # date for statistics file | localtime->strftime ('%F') does not work on windows
my $starttime = time(); # time in seconds since Jan 1, 1970
my $starttimestring; # starting time | localtime->strftime ('%F %R') does not work on windows
my $endtime; #
my $endtimestring; #
my $min; # Minute part of localtime array
my $hour; # hour part of localtime array
my $mday; # day of month part of localtime array
my $mon; # month part of localtime array
my $year; # year part of localtime array
my $proctime = 0.0; # total processing time in seconds
my $pproctime = 0.0; # partial processing time in seconds per subdir "Elapsed processing time: 00:00:01"
my $starttime = time(); # time in seconds since Jan 1, 1970
my $starttimestring; # starting time | localtime->strftime ('%F %R') does not work on windows
my $endtime; #
my $endtimestring; #
my $min; # Minute part of localtime array
my $hour; # hour part of localtime array
my $mday; # day of month part of localtime array
my $mon; # month part of localtime array
my $year; # year part of localtime array
my $total_elaped_time = 0.0; # total processing time in seconds
my $datatransfertime = 0.0; # total data transfer time in seconds "Data transfer time: 0.00 sec"
#my $pdatatranstime = 0.0; # partial data transfer time in seconds per subdir
my $wallclocktime; # total wallclock time in seconds
my $speedup; # ratio of processing time and wallclock time
my $dttratio = 0.0; # ration between datatransfer time and total time
my $wallclocktime; # total wallclock time in seconds
my $speedup; # ratio of processing time and wallclock time
my $dttratio = 0.0; # ratio between datatransfer time and total time
my $pidfile; # name of the pid file
my $ppid; # parent process id (this script originally)
my $cpid; # child process id (copy of this script)
my $startpath; # pathroot where the backup should start from
my @startpaths = undef; # array for multiple startpaths
my $actpath; # starting path actually processed
my $actpathdir; # name of the actually procces path for logging
my $actpath; # starting path actually processed
my $actpathdir; # name of the actually procces path for logging
my $maxdepth = 3; # number of directory level to dive into, right here all folders are processed with "-su=y"
my $depth = ($maxdepth - 1); # just one level above $maxdepth, down to here all folders are processed with "-su=n"
......@@ -189,14 +188,15 @@ my $sevecount = 0; # amount of ANS....S messages
my $SooScount = 0; # amount of ANS1329S "Server out of Space" messages
my $returnval = -1;
# due to the ISP statistics
my $objects_inspected = 0; # "Total number of objects inspected"
my $objects_backed_up = 0; # "Total number of objects backed up"
my $objects_updated = 0; # "Total number of objects updated"
my $objects_deleted = 0; # "Total number of objects deleted"
my $objects_expired = 0; # "Total number of objects expired"
my $objects_failed = 0; # "Total number of objects failed"
my $bytes_inspected = 0; # "Total number of bytes inspected"
my $bytes_transferred = 0; # "Total number of bytes transferred"
my $total_objects_inspected = 0; # "Total number of objects inspected"
my $total_objects_backed_up = 0; # "Total number of objects backed up"
my $total_objects_updated = 0; # "Total number of objects updated"
my $total_objects_deleted = 0; # "Total number of objects deleted"
my $total_objects_expired = 0; # "Total number of objects expired"
my $total_objects_failed = 0; # "Total number of objects failed"
my $total_bytes_inspected = 0; # "Total number of bytes inspected"
my $total_bytes_transferred = 0; # "Total number of bytes transferred"
my $total_transfer_time = 0; # "Total transfer time"
#filehandles
my $PPIDFILE;
......@@ -478,13 +478,6 @@ open $GLOBALLOGFILE, '<' , $globallog_filename or warn "cannot open global log f
while (my $line = <$GLOBALLOGFILE>)
{
my @temparray = undef;
my $val = 0.0;
my $unit = undef;
my $tsec = 0.0;
my $tmin = 0.0;
my $thour = 0.0;
#
# identify subdir
#
......@@ -512,80 +505,42 @@ while (my $line = <$GLOBALLOGFILE>)
#
# collect statistics of all jobs
#
if ( $line =~ /Total number of objects inspected/ )
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_inspected += $val;
}
elsif ($line =~ /Total number of objects backed up/)
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_backed_up += $val;
}
elsif ($line =~ /Total number of objects updated/)
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_updated += $val;
}
elsif ($line =~ /Total number of objects deleted/)
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_deleted += $val;
}
elsif ($line =~ /Total number of objects expired/)
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_expired += $val;
}
elsif ($line =~ /Total number of objects failed/)
if ( $line =~ /#profilinglog/ )
{
@temparray = split ':', $line;
$val = (pop @temparray);
$val =~ s/,//g; # just to eliminate grouping delimiter
$objects_failed += $val;
}
elsif ($line =~ /Total number of bytes inspected/)
{
@temparray = split ':', $line;
($val, $unit) = split ' ', $temparray[-1];
$val =~ s/,//g; # just to eliminate grouping delimiter
$val *= get_unit_mupliplier($unit);
$bytes_inspected += $val;
}
elsif ($line =~ /Total number of bytes transferred/)
{
@temparray = split ':', $line;
($val, $unit) = split ' ', $temparray[-1];
$val =~ s/,//g; # just to eliminate grouping delimiter
$val *= get_unit_mupliplier($unit);
$bytes_transferred += $val;
}
elsif ($line =~ /Data transfer time/)
{
@temparray = split ':', $line;
($val, $unit) = split ' ', $temparray[-1];
$val =~ s/,//g; # just to eliminate grouping delimiter
$datatransfertime += $val;
}
elsif ($line =~ /Elapsed processing time/)
{
(undef, $thour, $tmin, $tsec) = split ':', $line;
# (undef, $thour, $tmin, $tsec, $actpath) = split ':', $line;
$pproctime = $tsec + (60 * $tmin) + (3600 * $thour);
$proctime += $pproctime;
my $tline = sprintf "%10.10d ; %s", $pproctime, $actpathdir;
if ( $actpathdir ne $startpath )
{ push @proftimes, $tline; }
# reset variables for profiling
my $et ; # elapsed time
my $oi ; # objects inspected
my $ob ; # objects backed up
my $ou ; # objects updated
my $od ; # objects deleted
my $oe ; # objects expired
my $of ; # objects failed
my $bi ; # bytes inspected
my $bt ; # bytes transfered
my $dtt; # transfer time
my $rc = -1; # return code of child process
(undef, $et, $dir, $rc, $oi, $ob, $ou, $od, $oe, $of, $bi, $bt, $dtt) = split ';', $line;
$total_elaped_time += $et; # "Summary on elapsed time"
$total_objects_inspected += $oi; # "Total number of objects inspected"
$total_objects_backed_up += $ob; # "Total number of objects backed up"
$total_objects_updated += $ou; # "Total number of objects updated"
$total_objects_deleted += $od; # "Total number of objects deleted"
$total_objects_expired += $oe; # "Total number of objects expired"
$total_objects_failed += $of; # "Total number of objects failed"
$total_bytes_inspected += $bi; # "Total number of bytes inspected"
$total_bytes_transferred += $bt; # "Total number of bytes transferred"
$total_transfer_time += $dtt; # "Total transfer time"
my $tline = sprintf "%10.10d ; %s ; %d ; %d ; %d ; %d ; %d ; %d ; %d ; %lf ; %lf; %lf",
$et, $dir, $rc, $oi, $ob, $ou, $od, $oe, $of, $bi, $bt, $dtt;
# need to figure out why I implemented this vvv
if ( $actpathdir ne $startpath )
{
push @proftimes, $tline;
}
}
}
close $GLOBALLOGFILE;
......@@ -603,7 +558,9 @@ my @sproflines = sort { $b cmp $a } @proftimes;
# open profiling file
open $PROFFILE, '>', $proffilename
or warn "Cannot open Profiling file $proffilename";
# wirte lines
# write in index line
printf $PROFFILE "# Elapsed Time ; Directory; Return Code; Objects inspected; Objects backed up; Objects updated; Objects deleted; Objects expired; Objects failed; Bytes inspected; Bytes transferred, Data transfer time\n";
# write lines
foreach $line (@sproflines)
{ printf $PROFFILE "%s\n", $line; }
close $PROFFILE;
......@@ -627,14 +584,14 @@ close(ERRORFILE);
###############################################################################
###############################################################################
$speedup = $proctime / ($endtime - $starttime);
if ( $datatransfertime < 0.1 or $proctime < 0.1 )
$speedup = $total_elaped_time / ($endtime - $starttime);
if ( $datatransfertime < 0.1 or $total_elaped_time < 0.1 )
{ $dttratio = 0.0; }
else
{
$dttratio = $datatransfertime / $proctime * 100.;
$dttratio = $datatransfertime / $total_elaped_time * 100.;
}
$proctime = convert_time($proctime);
$total_elaped_time = convert_time($total_elaped_time);
$statfilename = File::Spec->canonpath($date.".dsmci-stats.txt");
open $STATFILE, ">", $statfilename
......@@ -648,19 +605,19 @@ foreach $actpath (@startpaths)
printf $STATFILE "-------------------------------------------------\n";
printf $STATFILE "Start time : %20s\n", $starttimestring;
printf $STATFILE "End time : %20s\n", $endtimestring;
printf $STATFILE "total processing time : %20s\n", $proctime;
printf $STATFILE "total processing time : %20s\n", $total_elaped_time;
printf $STATFILE "total wallclock time : %20s\n", $wallclocktime;
printf $STATFILE "effective speedup : %20.3lf using %d parallel threads\n", $speedup, $maxthreads;
printf $STATFILE "datatransfertime ratio: %20.3lf %%\n", $dttratio;
printf $STATFILE "-------------------------------------------------\n";
printf $STATFILE "Objects inspected : %20d\n", $objects_inspected;
printf $STATFILE "Objects backed up : %20d\n", $objects_backed_up;
printf $STATFILE "Objects updated : %20d\n", $objects_updated;
printf $STATFILE "Objects deleted : %20d\n", $objects_deleted;
printf $STATFILE "Objects expired : %20d\n", $objects_expired;
printf $STATFILE "Objects failed : %20d\n", $objects_failed;
printf $STATFILE "Bytes inspected : %20.3lf (GB)\n", $bytes_inspected;
printf $STATFILE "Bytes transferred : %20.3lf (GB)\n", $bytes_transferred;
printf $STATFILE "Objects inspected : %20d\n", $total_objects_inspected;
printf $STATFILE "Objects backed up : %20d\n", $total_objects_backed_up;
printf $STATFILE "Objects updated : %20d\n", $total_objects_updated;
printf $STATFILE "Objects deleted : %20d\n", $total_objects_deleted;
printf $STATFILE "Objects expired : %20d\n", $total_objects_expired;
printf $STATFILE "Objects failed : %20d\n", $total_objects_failed;
printf $STATFILE "Bytes inspected : %20.3lf (GB)\n", $total_bytes_inspected;
printf $STATFILE "Bytes transferred : %20.3lf (GB)\n", $total_bytes_transferred;
printf $STATFILE "-------------------------------------------------\n";
printf $STATFILE "Number of Errors : %20d\n", $errorcount;
printf $STATFILE "Number of Warnings : %20d\n", $warncount;
......@@ -795,6 +752,7 @@ sub in_array1
sub fork_backup_threads
{
my $switcher;
foreach $item (@allpaths)
{
# split path and SU-switcher
......@@ -829,6 +787,26 @@ sub fork_backup_threads
}
else
{ # child process
# reset variables for profiling
my $et = 0; # elapsed time
my $oi = 0; # objects inspected
my $ob = 0; # objects backed up
my $ou = 0; # objects updated
my $od = 0; # objects deleted
my $oe = 0; # objects expired
my $of = 0; # objects failed
my $bi = 0; # bytes inspected
my $bt = 0; # bytes transfered
my $dtt = 0; # transfer time
# some temporary variables
my @temparray; # just a temporary arry for splitting values
my $unit; # getting the unit of the value
my $thour;
my $tmin;
my $tsec;
# create own log file
$log_filename = $ppid . $$. $childlogapx;
......@@ -852,8 +830,8 @@ sub fork_backup_threads
# backup commandline
$command = "\"$dsmcbin\" i \"$dir\" -su=$switcher -optfile=\"$optfile\" >> $log_filename 2>&1";
if ( $debugmode == TRUE )
{ printf "%s\n", $command; }
if ( $debugmode == TRUE ) { printf "%s\n", $command; }
# record commandline in childlogfile
open $CHILDLOGFILE, ">", $log_filename;
printf $CHILDLOGFILE "CMD: >>%s<<\n\n", $command;
......@@ -862,11 +840,6 @@ if ( $debugmode == TRUE )
# do backup and pipe output to childlogfile
$childreturnvalue = system($command);
# add returnvalue to logfile
# open $CHILDLOGFILE, ">>", $log_filename;
# printf $CHILDLOGFILE "\nRETURNVAL: %d\n", $childreturnvalue;
# close $CHILDLOGFILE;
# copy logfile to global log file
open $GLOBALLOGFILE, ">>", $globallog_filename;
# set exclusive lock on file - or wait for the actual lock to resume
......@@ -874,15 +847,79 @@ if ( $debugmode == TRUE )
open $CHILDLOGFILE, "<", $log_filename;
while (my $line = <$CHILDLOGFILE>)
{
if ($line =~ /Elapsed processing time/)
# copy each line to gobal log file
printf $GLOBALLOGFILE "%s", $line;
# collect data for profiling log
if ( $line =~ /Total number of objects inspected/ )
{
@temparray = split ':', $line;
$oi = (pop @temparray);
$oi =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Total number of objects backed up/)
{
@temparray = split ':', $line;
$ob = (pop @temparray);
$ob =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Total number of objects updated/)
{
@temparray = split ':', $line;
$ou = (pop @temparray);
$ou =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Total number of objects deleted/)
{
$line =~ s/\n$//;
printf $GLOBALLOGFILE "%s : SU%s : %s\n", $line, $switcher, $dir;
@temparray = split ':', $line;
$od = (pop @temparray);
$od =~ s/,//g; # just to eliminate grouping delimiter
}
else # nothing special to do
elsif ($line =~ /Total number of objects expired/)
{
printf $GLOBALLOGFILE "%s", $line;
@temparray = split ':', $line;
$oe = (pop @temparray);
$oe =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Total number of objects failed/)
{
@temparray = split ':', $line;
$of = (pop @temparray);
$of =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Total number of bytes inspected/)
{
@temparray = split ':', $line;
($bi, $unit) = split ' ', $temparray[-1];
$bi =~ s/,//g; # just to eliminate grouping delimiter
$bi *= get_unit_mupliplier($unit);
}
elsif ($line =~ /Total number of bytes transferred/)
{
@temparray = split ':', $line;
($bt, $unit) = split ' ', $temparray[-1];
$bt =~ s/,//g; # just to eliminate grouping delimiter
$bt *= get_unit_mupliplier($unit);
}
elsif ($line =~ /Data transfer time/)
{
@temparray = split ':', $line;
($dtt, $unit) = split ' ', $temparray[-1];
$dtt =~ s/,//g; # just to eliminate grouping delimiter
}
elsif ($line =~ /Elapsed processing time/)
{
(undef, $thour, $tmin, $tsec) = split ':', $line;
$et = $tsec + (60 * $tmin) + (3600 * $thour);
}
}
# print line for profiling log
printf $GLOBALLOGFILE "#profilinglog ; %d ; %s ; %d ; %d ; %d ; %d ; %d ; %d ; %d ; %.3lf ; %.3lf; %.3lf",
$et, $dir, $childreturnvalue, $oi, $ob, $ou, $od, $oe, $of, $bi, $bt, $dtt;
if ( $debugmode == 2 )
{
printf "#profilinglog ; %d ; %s ; %d ;% 15.15d ; % 15.15d ; % 15.15d ; % 15.15d ; % 15.15d ; % 15.15d ; %15.3lf ; %15.3lf; %15.3lf",
$et, $dir, $childreturnvalue, $oi, $ob, $ou, $od, $oe, $of, $bi, $bt, $dtt;
}
close $CHILDLOGFILE;
printf $GLOBALLOGFILE "\nRETURNVAL: %d\n", $childreturnvalue;
......@@ -892,7 +929,7 @@ if ( $debugmode == TRUE )
# remove original child log file
unlink $log_filename;
# return rc and finish thread
# return rc and finish thread
exit $childreturnvalue;
}
}
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment