diff --git a/xCAT-probe/subcmds/osdeploy b/xCAT-probe/subcmds/osdeploy index 6bc76d930..4ef4d689f 100755 --- a/xCAT-probe/subcmds/osdeploy +++ b/xCAT-probe/subcmds/osdeploy @@ -68,7 +68,8 @@ Options: -p Show elapsed time of each stage during provision for each node Support 2 output format: 'compact': Elapsed time of provision for each node. - 'details': Elapsed time for DHCP, RPM, POSTSCRIPTS and POSTBOOTSCRIPTS stages, and time for whole provision. + 'phase' : Elapsed time for DHCP, RPM, POSTSCRIPTS and POSTBOOTSCRIPTS stages, and time for whole provision. + 'origin' : Show origin time of each stage. "; @@ -121,7 +122,7 @@ if ($rollforward_time_of_replay) { } if ($performance) { - if ($performance ne "compact" and $performance ne "details") { + if ($performance ne "compact" and $performance ne "phase" and $performance ne "origin") { probe_utils->send_msg("stdout", "f", "Unsupported parameter for option '-p'"); probe_utils->send_msg("stdout", "", "$::USAGE"); exit 1; @@ -143,7 +144,6 @@ exit $rst if ($rst); # record every status's start time and end time for each node # $node_status_time{$node}{$status}{start_time} = $start_time; my %node_status_time = () if ($performance); -my $provision_type = $::DISKFUL; if ($rollforward_time_of_replay) { $monitor = 0; @@ -567,23 +567,25 @@ sub conclusion_report { Calculate the performance of provision (for each node) Arguments: performance: compact: calculate how much time spent for provision - details: calculate how much time spent for each status (DHCP, RPM, POSTSCRIPTS, POSTBOOTSCRIPTS) - reserve: reserve for diskless + phase: calculate how much time spent for each status (DHCP, RPM, POSTSCRIPTS, POSTBOOTSCRIPTS) + origin : show time point for each status + reserve: reserve for other type Returns: =cut #------------------------------------------ sub performance_calculation { my $is_success = shift; - print Dumper(%node_status_time); + #print Dumper(%node_status_time); - return if ((keys %node_status_time == 1 and $node_status_time{all}) or !%node_status_time); + return if (!%node_status_time); probe_utils->send_msg("stdout", "", "-----------node provision performance-----------"); - my %all_spend_time = (); + # Currently, only diskful is supported + my $provision_type = $::DISKFUL; + my @status_for_time = (); - my $warninfo; my $isnull = 0; my $length_node = 20; @@ -591,40 +593,61 @@ sub performance_calculation { # print table's first line # @status_for_time: the status that needed to calculate time - if ($provision_type == $::DISKFUL and $performance eq "reserve") { - print "NODE $space DHCP BOOTLOADER KERNEL INITRD KICKSTART RPM POST POSTBOOT COMPLETED\n"; - @status_for_time = ($::STATE_DHCP, $::STATE_BOOTLODER, $::STATE_KERNEL, $::STATE_INITRD, $::STATE_KICKSTART, $::STATE_INSTALLRPM, $::STATE_POSTSCRIPT, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); - } elsif ($provision_type == $::DISKFUL and $performance eq "details") { - print "NODE $space DHCP RPM POST POSTBOOT COMPLETED\n"; - @status_for_time = ($::STATE_DHCP, $::STATE_INSTALLRPM, $::STATE_POSTSCRIPT, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); - } elsif ($provision_type == $::DISKLESS and $performance eq "reserve") { - print "NODE $space DHCP BOOTLOADER KERNEL INITRD NETBOOTING ROOTIMG POSTBOOT COMPLETED\n"; - @status_for_time = ($::STATE_DHCP, $::STATE_BOOTLODER, $::STATE_KERNEL, $::STATE_INITRD, $::STATE_NETBOOTING, $::STATE_ROOTIMG, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); - } elsif ($performance eq "compact") { - print "NODE $space COMPLETED\n"; + + my @title_lines = ( + "NODE $space ELAPSED\n", + "NODE $space SVRBOOT RPM POST POSTBOOT ELAPSED\n", + "NODE $space RPOWER DHCP BOOTLOADER KERNEL INITRD RPM POST POSTBOOT COMPLETED\n", + "NODE $space RPOWER DHCP BOOTLOADER KERNEL INITRD NETBOOTING ROOTIMG POSTBOOT COMPLETED\n", + "NODE $space DHCP BOOTLOADER KERNEL INITRD NETBOOTING ROOTIMG POSTBOOT ELAPSED\n"); + + if ($performance eq "compact") { + print $title_lines[0]; @status_for_time = ($::STATE_COMPLETED); } + if ($performance eq "phase") { + print $title_lines[1]; + @status_for_time = ($::STATE_DHCP, $::STATE_INSTALLRPM, $::STATE_POSTSCRIPT, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); + } + + if ($performance eq "origin") { + if ($provision_type == $::DISKFUL){ + print $title_lines[2]; + @status_for_time = ($::STATE_POWER_ON, $::STATE_DHCP, $::STATE_BOOTLODER, $::STATE_KERNEL, $::STATE_INITRD, $::STATE_INSTALLRPM, $::STATE_POSTSCRIPT, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); + } else { # reserved for diskless + print $title_lines[3]; + @status_for_time = ($::STATE_POWER_ON, $::STATE_DHCP, $::STATE_BOOTLODER, $::STATE_KERNEL, $::STATE_INITRD, $::STATE_NETBOOTING, $::STATE_ROOTIMG, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); + } + } + + if ($performance eq "reserve") { + print $title_lines[4]; + @status_for_time = ($::STATE_DHCP, $::STATE_BOOTLODER, $::STATE_KERNEL, $::STATE_INITRD, $::STATE_NETBOOTING, $::STATE_ROOTIMG, $::STATE_POSTBOOTSCRIPT, $::STATE_COMPLETED); + } + # calculate time for each node and status foreach my $node (keys %node_status_time) { - next if ($node eq "all"); - # if did not get start time of power on, use osdeploy start time and show warning info - if ((!$node_status_time{$node}{$::STATE_POWER_ON}{start_time}) and $node_status_time{all}) { - $node_status_time{$node}{$::STATE_POWER_ON}{start_time} = $node_status_time{all}; - $warninfo = "Did not get start time from log during running, use xcatprobe start time"; - } - - # get the start time of the first node - if ($all_spend_time{start_time}) { - $all_spend_time{start_time} = $node_status_time{$node}{$::STATE_POWER_ON}{start_time} if ($all_spend_time{start_time} > $node_status_time{$node}{$::STATE_POWER_ON}{start_time}); - } else { - $all_spend_time{start_time} = $node_status_time{$node}{$::STATE_POWER_ON}{start_time}; - } - - # get the end time of the last node - if ($node_status_time{$node}{$::STATE_COMPLETED}{start_time}) { - $all_spend_time{end_time} = $node_status_time{$node}{$::STATE_COMPLETED}{start_time} if ($all_spend_time{end_time} < $node_status_time{$node}{$::STATE_COMPLETED}{start_time}); + if ($performance eq "origin") { + my @time_origin = (); + foreach my $status (@status_for_time) { + if ($node_status_time{$node}{$status}{time_point}) { + if ($status == $::STATE_DHCP and $node_status_time{$node}{$::STATE_DHCP}{end_time} > $node_status_time{$node}{$::STATE_BOOTLODER}{start_time}){ + push @time_origin, "NULL* "; + $isnull = 1; + } else { + push @time_origin, $node_status_time{$node}{$status}{time_point}; + } + } else { + push @time_origin, "NULL* "; + $isnull = 1; + } + } + my $time_str = join(" ", @time_origin); + $space = " " x ($length_node - length($node)); + print "$node $space $time_str\n"; + next; } # get the start time and end time for each step @@ -632,41 +655,28 @@ sub performance_calculation { foreach my $status (@status_for_time) { my $tmp_status; my $tmp_detail_status; - if ($performance eq "details" and $provision_type == $::DISKFUL) { - # when details, if the status is DHCP, use power on time as it's start time + if ($performance eq "phase") { + # when phase, if the status is DHCP, use power on time as it's start time $tmp_detail_status = $::STATE_DHCP; } else { - # if not details, power on time is the start time for each steps + # if not phase, power on time is the start time for each steps $tmp_detail_status = $::STATE_COMPLETED; } if ($status <= $tmp_detail_status or $status == $::STATE_COMPLETED) { $tmp_status = $::STATE_POWER_ON; - if ($warninfo and $status == $::STATE_DHCP) { - push @timeinfo, "NULL* "; - $isnull = 1; - $all_spend_time{$status}{rst} = "NULL* "; - next; - } } else { $tmp_status = $status; } - my $tmp_end_time; - $tmp_end_time = $node_status_time{$node}{$status}{end_time} if ($node_status_time{$node}{$status}{end_time}); + my $tmp_start_time = $node_status_time{$node}{$tmp_status}{start_time}; + my $tmp_end_time = $node_status_time{$node}{$status}{end_time}; $tmp_end_time = $node_status_time{$node}{$status}{start_time} if ($status != $::STATE_DHCP and $status != $::STATE_INSTALLRPM and $status != $::STATE_POSTSCRIPT and $status != $::STATE_POSTBOOTSCRIPT and $node_status_time{$node}{$status}{start_time}); - if ($node_status_time{$node}{$tmp_status}{start_time} && $tmp_end_time) { - if ($all_spend_time{$status}{start_time}) { - $all_spend_time{$status}{start_time} = $node_status_time{$node}{$tmp_status}{start_time} if ($all_spend_time{$status}{start_time} > $node_status_time{$node}{$tmp_status}{start_time}); - } else { - $all_spend_time{$status}{start_time} = $node_status_time{$node}{$tmp_status}{start_time}; - } - $all_spend_time{$status}{end_time} = $tmp_end_time if ($all_spend_time{$status}{end_time} < $tmp_end_time); - push @timeinfo, probe_utils->convert_second_to_time($tmp_end_time - $node_status_time{$node}{$tmp_status}{start_time}); + if ($tmp_start_time && $tmp_end_time) { + push @timeinfo, probe_utils->convert_second_to_time($tmp_end_time - $tmp_start_time); } else { push @timeinfo, "NULL* "; - $all_spend_time{$status}{rst} = "NULL* "; $isnull = 1; } } @@ -676,22 +686,7 @@ sub performance_calculation { print "$node $space $time_str\n"; } - # @time_rst is used to record time of ALL - my @time_rst = (); - foreach my $status (@status_for_time) { - if ($all_spend_time{$status}{rst} eq "NULL* ") { - push @time_rst, $all_spend_time{$status}{rst}; - } else { - my $status_time = probe_utils->convert_second_to_time($all_spend_time{$status}{end_time} - $all_spend_time{$status}{start_time}); - push @time_rst, $status_time; - } - } - - my $time_str = join(" ", @time_rst); - $space = " " x ($length_node - 3); - print "ALL $space $time_str\n"; probe_utils->send_msg("stdout", "", "------------------------------------------------"); - probe_utils->send_msg("stdout", "", "$warninfo") if ($warninfo); if ($isnull and $is_success) { my $command_input = "xcatprobe -w $program_name"; @@ -735,8 +730,6 @@ Start capturing every message during OS provision process.... "; probe_utils->send_msg("stdout", "", "$startline"); - $node_status_time{all} = time(); - my @openfilepids; my @openfilefds; my %fd_filetype_map; @@ -957,7 +950,10 @@ sub handle_dhcp_msg { $ipnodemap{$ip} = $node; set_node_state($node_state_ref, $node, $::STATE_DHCP); - $node_status_time{$node}{$::STATE_DHCP}{end_time} = $log_ref->{time} if ($performance and !$node_status_time{$node}{$::STATE_DHCP}{end_time}); + if ($performance and !$node_status_time{$node}{$::STATE_DHCP}{end_time}) { + $node_status_time{$node}{$::STATE_DHCP}{time_point} = $log_ref->{time_record}; + $node_status_time{$node}{$::STATE_DHCP}{end_time} = $log_ref->{time}; + } } } elsif ($log_ref->{msg} =~ /BOOTREQUEST\s+from\s+(.+)\s+via\s+([^:]+)(.*)/) { my $mac = $1; @@ -986,7 +982,10 @@ sub handle_dhcp_msg { $ipnodemap{$ip} = $node; set_node_state($node_state_ref, $node, $::STATE_DHCP); - $node_status_time{$node}{$::STATE_DHCP}{end_time} = $log_ref->{time} if ($performance and !$node_status_time{$node}{$::STATE_DHCP}{end_time}); + if ($performance and !$node_status_time{$node}{$::STATE_DHCP}{end_time}) { + $node_status_time{$node}{$::STATE_DHCP}{end_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_DHCP}{time_point} = $log_ref->{time_record}; + } } } } @@ -1018,13 +1017,22 @@ sub handle_tftp_msg { if ($file =~ /xcat\/xnba.*/i or $file =~ /\/boot\/grub2\/powerpc-ieee1275\//i or $file =~ /\/yb\/node\/yaboot\-/i) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_BOOTLODER); - $node_status_time{$ipnodemap{$ip}}{$::STATE_BOOTLODER}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_BOOTLODER}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_BOOTLODER}{time_point} = $log_ref->{time_record}; + } } elsif ($file =~ /vmlinuz|inst64|linux/) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_KERNEL); - $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{time_point} = $log_ref->{time_record}; + } } elsif ($file =~ /initrd/i) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_INITRD); - $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{time_point} = $log_ref->{time_record}; + } } } } @@ -1061,26 +1069,39 @@ sub handle_http_msg { if ($file =~ /vmlinuz|inst64/i or ($file =~ /linux/i and $file =~ /osimage/i)) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_KERNEL); - $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_KERNEL}{time_point} = $log_ref->{time_record}; + } push (@{ $node_state_ref->{ $ipnodemap{$ip} }{errors}{$::STATE_KERNEL} }, "$record failed with $http_code") if ($http_code >= 400); } elsif ($file =~ /initrd/i and $file =~ /osimage/i) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_INITRD); - $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_INITRD}{time_point} = $log_ref->{time_record}; + } push (@{ $node_state_ref->{ $ipnodemap{$ip} }{errors}{$::STATE_INITRD} }, "$record failed with $http_code") if ($http_code >= 400); } elsif (($file =~ /^\/install\/autoinst\//i) and ($file !~ /getinstdisk$/i) and ($file !~ /\.pre$/i) and ($file !~ /\.post$/i)) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_KICKSTART); - $node_status_time{$ipnodemap{$ip}}{$::STATE_KICKSTART}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_KICKSTART}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_KICKSTART}{time_point} = $log_ref->{time_record}; + } push (@{ $node_state_ref->{ $ipnodemap{$ip} }{errors}{$::STATE_KICKSTART} }, "$record failed with $http_code") if ($http_code >= 400); } elsif ($file =~ /\.deb$/i or $file =~ /\/Packages\/.+\.rpm$/ or $file =~ /\/suse\/noarch\/.+\.rpm$/i) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_INSTALLRPM); if ($performance) { $node_status_time{$ipnodemap{$ip}}{$::STATE_INSTALLRPM}{end_time} = $log_ref->{time}; $node_status_time{$ipnodemap{$ip}}{$::STATE_INSTALLRPM}{start_time} = $log_ref->{time} unless ( $node_status_time{$ipnodemap{$ip}}{$::STATE_INSTALLRPM}{start_time} ); + $node_status_time{$ipnodemap{$ip}}{$::STATE_INSTALLRPM}{time_point} = $log_ref->{time_record} unless ( $node_status_time{$ipnodemap{$ip}}{$::STATE_INSTALLRPM}{time_point} ); } push (@{ $node_state_ref->{ $ipnodemap{$ip} }{errors}{$::STATE_INSTALLRPM} }, "$record failed with $http_code") if ($http_code >= 400); } elsif ($file =~ /rootimg/) { set_node_state($node_state_ref, $ipnodemap{$ip}, $::STATE_ROOTIMG); - $node_status_time{$ipnodemap{$ip}}{$::STATE_ROOTIMG}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$ipnodemap{$ip}}{$::STATE_ROOTIMG}{start_time} = $log_ref->{time}; + $node_status_time{$ipnodemap{$ip}}{$::STATE_ROOTIMG}{time_point} = $log_ref->{time_record}; + } } } } @@ -1118,7 +1139,10 @@ sub handle_cluster_msg { probe_utils->send_msg("stdout", "d", "[$node] $log_ref->{time_record} Use command $command to reboot node $node") if ($monitor); push(@{ $node_state_ref->{$node}{log} }, $log_ref->{msg}) if ($debug); set_node_state($node_state_ref, $node, $::STATE_POWER_ON); - $node_status_time{$node}{$::STATE_POWER_ON}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$node}{$::STATE_POWER_ON}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_POWER_ON}{time_point} = $log_ref->{time_record}; + } } } } @@ -1135,16 +1159,28 @@ sub handle_cluster_msg { if ($status eq "installing") { set_node_state($node_state_ref, $node, $::STATE_INSTALLING); - $node_status_time{$node}{$::STATE_INSTALLING}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$node}{$::STATE_INSTALLING}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_INSTALLING}{time_point} = $log_ref->{time_record}; + } } elsif ($status eq "powering-on") { set_node_state($node_state_ref, $node, $::STATE_POWERINGON); - $node_status_time{$node}{$::STATE_POWERINGON}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$node}{$::STATE_POWERINGON}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_POWERINGON}{time_point} = $log_ref->{time_record}; + } } elsif ($status eq "booting") { set_node_state($node_state_ref, $node, $::STATE_BOOTING); - $node_status_time{$node}{$::STATE_BOOTING}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$node}{$::STATE_BOOTING}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_BOOTING}{time_point} = $log_ref->{time_record}; + } } elsif ($status eq "netbooting") { set_node_state($node_state_ref, $node, $::STATE_NETBOOTING); - $node_status_time{$node}{$::STATE_NETBOOTING}{start_time} = $log_ref->{time} if ($performance); + if ($performance) { + $node_status_time{$node}{$::STATE_NETBOOTING}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_NETBOOTING}{time_point} = $log_ref->{time_record}; + } } elsif ($status eq "failed") { $node_state_ref->{$node}{done} = 1; } @@ -1178,6 +1214,7 @@ sub handle_compute_msg { set_node_state($node_state_ref, $node, $::STATE_POSTSCRIPT); if ($performance) { $node_status_time{$node}{$::STATE_POSTSCRIPT}{start_time} = $log_ref->{time} unless ($node_status_time{$node}{$::STATE_POSTSCRIPT}{start_time}); + $node_status_time{$node}{$::STATE_POSTSCRIPT}{time_point} = $log_ref->{time_record} unless ($node_status_time{$node}{$::STATE_POSTSCRIPT}{time_point}); } } elsif ($log_ref->{msg} =~ /postscript (.+) return with (\d+)/) { my $script_name = $1; @@ -1194,6 +1231,7 @@ sub handle_compute_msg { set_node_state($node_state_ref, $node, $::STATE_POSTBOOTSCRIPT); if ($performance) { $node_status_time{$node}{$::STATE_POSTBOOTSCRIPT}{start_time} = $log_ref->{time} unless ($node_status_time{$node}{$::STATE_POSTBOOTSCRIPT}{start_time}); + $node_status_time{$node}{$::STATE_POSTBOOTSCRIPT}{time_point} = $log_ref->{time_record} unless ($node_status_time{$node}{$::STATE_POSTBOOTSCRIPT}{time_point}); } } elsif ($log_ref->{msg} =~ /postbootscript (.+) return with (\d+)/) { my $script_name = $1; @@ -1210,7 +1248,10 @@ sub handle_compute_msg { set_node_state($node_state_ref, $node, $::STATE_COMPLETED); $node_state_ref->{$node}{done} = 1; probe_utils->send_msg("stdout", "o", "[$node] $log_ref->{time_record} provision completed") if ($monitor); - $node_status_time{$node}{$::STATE_COMPLETED}{start_time} = $log_ref->{time}; + if ($performance) { + $node_status_time{$node}{$::STATE_COMPLETED}{start_time} = $log_ref->{time}; + $node_status_time{$node}{$::STATE_COMPLETED}{time_point} = $log_ref->{time_record}; + } } } }