From b53486e08377506179e5da0abe8b960dba5c483a Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Tue, 27 Jan 2015 17:02:02 -0500 Subject: ktest: Add timings for commands I find that I usually like to see how long a make or other command takes, and adding a start and end time and reporting how long each command runs (in seconds) is helpful. Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index b9cd036f0442..27273c228d92 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -1534,10 +1534,14 @@ sub fail { sub run_command { my ($command, $redirect) = @_; + my $start_time; + my $end_time; my $dolog = 0; my $dord = 0; my $pid; + $start_time = time; + $command =~ s/\$SSH_USER/$ssh_user/g; $command =~ s/\$MACHINE/$machine/g; @@ -1570,6 +1574,15 @@ sub run_command { close(LOG) if ($dolog); close(RD) if ($dord); + $end_time = time; + my $delta = $end_time - $start_time; + + if ($delta == 1) { + doprint "[1 second] "; + } else { + doprint "[$delta seconds] "; + } + if ($failed) { doprint "FAILED!\n"; } else { -- cgit v1.2.3-59-g8ed1b From 988427829bcd230c78106d28dbfa85d45d182909 Mon Sep 17 00:00:00 2001 From: Josh Poimboeuf Date: Tue, 27 Jan 2015 12:10:04 -0600 Subject: ktest: Restore tty settings after closing console When ktest runs the console program as a child process, the parent and child share the same tty for stdin and stderr. This is problematic when using a libvirt target. The "virsh console" program makes a lot of changes to the tty settings, making ktest's output hard to read (carriage returns don't work). After ktest exits, the terminal is unusable (CRs broken, stdin isn't echoed). I think the best way to fix this issue would be to create a pseudoterminal (pty pair) so the child process would have a dedicated tty, and then use pipes to connect the two ttys. I'm not sure if that's overkill, but it's far beyond my current Perl abilities. This patch is a much easier way to (partially) fix this issue. It saves the tty settings before opening the console and restores them after closing it. There are still a few places where ktest prints mangled output while the console is open, but the output is much more legible overall, and the terminal works just fine after ktest exits. Link: http://lkml.kernel.org/r/1bb89abc0025cf1d6da657c7ba58bbeb4381a515.1422382008.git.jpoimboe@redhat.com Signed-off-by: Josh Poimboeuf Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 27273c228d92..1dae000f79f8 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -178,6 +178,7 @@ my $checkout; my $localversion; my $iteration = 0; my $successes = 0; +my $stty; my $bisect_good; my $bisect_bad; @@ -1349,6 +1350,9 @@ sub open_console { my $flags; + # save terminal settings + $stty = `stty -g`; + my $pid = open($fp, "$console|") or dodie "Can't open console $console"; @@ -1368,6 +1372,9 @@ sub close_console { print "closing!\n"; close($fp); + + # restore terminal settings + system("stty $stty"); } sub start_monitor { -- cgit v1.2.3-59-g8ed1b From 38fa3dc15c6948135977d50ecf90061f21cebc15 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Wed, 28 Jan 2015 09:43:01 -0500 Subject: ktest: Show times for build, install, boot and test Seeing the times for how long a build, install, reboot and the test takes is helpful for analyzing the test process. Seeing how different changes affect the timings. Show the build, install, boot and test times when at the end of the test, or between each interval for tests that do those mulitple times (like bisect and patchcheck). Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 109 +++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 105 insertions(+), 4 deletions(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 1dae000f79f8..177319822401 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -198,6 +198,11 @@ my $patchcheck_start; my $patchcheck_cherry; my $patchcheck_end; +my $build_time; +my $install_time; +my $reboot_time; +my $test_time; + # set when a test is something other that just building or install # which would require more options. my $buildonly = 1; @@ -555,6 +560,66 @@ sub get_mandatory_config { } } +sub show_time { + my ($time) = @_; + + my $hours = 0; + my $minutes = 0; + + if ($time > 3600) { + $hours = int($time / 3600); + $time -= $hours * 3600; + } + if ($time > 60) { + $minutes = int($time / 60); + $time -= $minutes * 60; + } + + if ($hours > 0) { + doprint "$hours hour"; + doprint "s" if ($hours > 1); + doprint " "; + } + + if ($minutes > 0) { + doprint "$minutes minute"; + doprint "s" if ($minutes > 1); + doprint " "; + } + + doprint "$time second"; + doprint "s" if ($time != 1); +} + +sub print_times { + doprint "\n"; + if ($build_time) { + doprint "Build time: "; + show_time($build_time); + doprint "\n"; + } + if ($install_time) { + doprint "Install time: "; + show_time($install_time); + doprint "\n"; + } + if ($reboot_time) { + doprint "Reboot time: "; + show_time($reboot_time); + doprint "\n"; + } + if ($test_time) { + doprint "Test time: "; + show_time($test_time); + doprint "\n"; + } + # reset for iterations like bisect + $build_time = 0; + $install_time = 0; + $reboot_time = 0; + $test_time = 0; +} + sub get_mandatory_configs { get_mandatory_config("MACHINE"); get_mandatory_config("BUILD_DIR"); @@ -1786,6 +1851,8 @@ sub monitor { my $skip_call_trace = 0; my $loops; + my $start_time = time; + wait_for_monitor 5; my $line; @@ -1910,6 +1977,9 @@ sub monitor { } } + my $end_time = time; + $reboot_time = $end_time - $start_time; + close(DMESG); if ($bug) { @@ -1958,6 +2028,8 @@ sub install { return if ($no_install); + my $start_time = time; + if (defined($pre_install)) { my $cp_pre_install = eval_kernel_version $pre_install; run_command "$cp_pre_install" or @@ -1989,6 +2061,8 @@ sub install { if (!$install_mods) { do_post_install; doprint "No modules needed\n"; + my $end_time = time; + $install_time = $end_time - $start_time; return; } @@ -2016,6 +2090,9 @@ sub install { run_ssh "rm -f /tmp/$modtar"; do_post_install; + + my $end_time = time; + $install_time = $end_time - $start_time; } sub get_version { @@ -2228,6 +2305,8 @@ sub build { unlink $buildlog; + my $start_time = time; + # Failed builds should not reboot the target my $save_no_reboot = $no_reboot; $no_reboot = 1; @@ -2313,6 +2392,9 @@ sub build { $no_reboot = $save_no_reboot; + my $end_time = time; + $build_time = $end_time - $start_time; + return 1; } @@ -2403,6 +2485,8 @@ sub do_run_test { my $bug = 0; my $bug_ignored = 0; + my $start_time = time; + wait_for_monitor 1; doprint "run test $run_test\n"; @@ -2469,6 +2553,9 @@ sub do_run_test { waitpid $child_pid, 0; $child_exit = $?; + my $end_time = time; + $test_time = $end_time - $start_time; + if (!$bug && $in_bisect) { if (defined($bisect_ret_good)) { if ($child_exit == $bisect_ret_good) { @@ -2775,6 +2862,7 @@ sub bisect { do { $result = run_bisect $type; $test = run_git_bisect "git bisect $result"; + print_times; } while ($test); run_command "git bisect log" or @@ -3188,6 +3276,7 @@ sub config_bisect { do { $ret = run_config_bisect \%good_configs, \%bad_configs; + print_times; } while (!$ret); return $ret if ($ret < 0); @@ -3317,10 +3406,12 @@ sub patchcheck { do_run_test or $failed = 1; } end_monitor; - return 0 if ($failed); - + if ($failed) { + print_times; + return 0; + } patchcheck_reboot; - + print_times; } $in_patchcheck = 0; success $i; @@ -4020,6 +4111,11 @@ for (my $i = 1; $i <= $opt{"NUM_TESTS"}; $i++) { $iteration = $i; + $build_time = 0; + $install_time = 0; + $reboot_time = 0; + $test_time = 0; + undef %force_config; my $makecmd = set_test_option("MAKE_CMD", $i); @@ -4183,9 +4279,14 @@ for (my $i = 1; $i <= $opt{"NUM_TESTS"}; $i++) { do_run_test or $failed = 1; } end_monitor; - next if ($failed); + if ($failed) { + print_times; + next; + } } + print_times; + success $i; } -- cgit v1.2.3-59-g8ed1b From 64d982838e89e0d3981bfe825e0e76b36e106332 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Wed, 28 Jan 2015 15:17:35 -0500 Subject: ktest: Rename start_monitor_and_boot to start_monitor_and_install The function start_monitor_and_boot is a misnomer. It use to, but now it starts the monitor and installs. It does not boot. Rename it before I get confused by it again. Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 177319822401..6ae890a0d486 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -2105,7 +2105,7 @@ sub get_version { $have_version = 1; } -sub start_monitor_and_boot { +sub start_monitor_and_install { # Make sure the stable kernel has finished booting # Install bisects, don't need console @@ -2656,7 +2656,7 @@ sub run_bisect_test { dodie "Failed on build" if $failed; # Now boot the box - start_monitor_and_boot or $failed = 1; + start_monitor_and_install or $failed = 1; if ($type ne "boot") { if ($failed && $bisect_skip) { @@ -3400,7 +3400,7 @@ sub patchcheck { my $failed = 0; - start_monitor_and_boot or $failed = 1; + start_monitor_and_install or $failed = 1; if (!$failed && $type ne "boot"){ do_run_test or $failed = 1; @@ -3864,7 +3864,7 @@ sub make_min_config { my $failed = 0; build "oldconfig" or $failed = 1; if (!$failed) { - start_monitor_and_boot or $failed = 1; + start_monitor_and_install or $failed = 1; if ($type eq "test" && !$failed) { do_run_test or $failed = 1; @@ -4273,7 +4273,7 @@ for (my $i = 1; $i <= $opt{"NUM_TESTS"}; $i++) { if ($test_type ne "build") { my $failed = 0; - start_monitor_and_boot or $failed = 1; + start_monitor_and_install or $failed = 1; if (!$failed && $test_type ne "boot" && defined($run_test)) { do_run_test or $failed = 1; -- cgit v1.2.3-59-g8ed1b From 9f2cdcbbb90e70e5e8fe6cd30151b8ac1c8745ac Mon Sep 17 00:00:00 2001 From: Josh Poimboeuf Date: Wed, 28 Jan 2015 13:38:38 -0600 Subject: ktest: Give console process a dedicated tty Create a pseudoterminal (pty pair) to give the console a dedicated tty so it doesn't mess with ktest's terminal settings. Link: http://lkml.kernel.org/r/37b0127f9efad09ff4fc994334db998141e4f6ca.1422473610.git.jpoimboe@redhat.com Signed-off-by: Josh Poimboeuf Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 66 ++++++++++++++++++++++++++++++++++++++------ 1 file changed, 57 insertions(+), 9 deletions(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 6ae890a0d486..2d3191693567 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -1410,23 +1410,71 @@ sub dodie { die @_, "\n"; } -sub open_console { - my ($fp) = @_; +sub create_pty { + my ($ptm, $pts) = @_; + my $tmp; + my $TIOCSPTLCK = 0x40045431; + my $TIOCGPTN = 0x80045430; + + sysopen($ptm, "/dev/ptmx", O_RDWR | O_NONBLOCK) or + dodie "Cant open /dev/ptmx"; + + # unlockpt() + $tmp = pack("i", 0); + ioctl($ptm, $TIOCSPTLCK, $tmp) or + dodie "ioctl TIOCSPTLCK for /dev/ptmx failed"; + + # ptsname() + ioctl($ptm, $TIOCGPTN, $tmp) or + dodie "ioctl TIOCGPTN for /dev/ptmx failed"; + $tmp = unpack("i", $tmp); + + sysopen($pts, "/dev/pts/$tmp", O_RDWR | O_NONBLOCK) or + dodie "Can't open /dev/pts/$tmp"; +} + +sub exec_console { + my ($ptm, $pts) = @_; + + close($ptm); + + close(\*STDIN); + close(\*STDOUT); + close(\*STDERR); - my $flags; + open(\*STDIN, '<&', $pts); + open(\*STDOUT, '>&', $pts); + open(\*STDERR, '>&', $pts); + + close($pts); + + exec $console or + dodie "Can't open console $console"; +} + +sub open_console { + my ($ptm) = @_; + my $pts = \*PTSFD; + my $pid; # save terminal settings $stty = `stty -g`; - my $pid = open($fp, "$console|") or - dodie "Can't open console $console"; + create_pty($ptm, $pts); - $flags = fcntl($fp, F_GETFL, 0) or - dodie "Can't get flags for the socket: $!"; - $flags = fcntl($fp, F_SETFL, $flags | O_NONBLOCK) or - dodie "Can't set flags for the socket: $!"; + $pid = fork; + + if (!$pid) { + # child + exec_console($ptm, $pts) + } + + # parent + close($pts); return $pid; + + open(PTSFD, "Stop perl from warning about single use of PTSFD"); } sub close_console { -- cgit v1.2.3-59-g8ed1b From 9d2f7f051b8917305ea20ed79ff08254ea73f26d Mon Sep 17 00:00:00 2001 From: Josh Poimboeuf Date: Wed, 28 Jan 2015 13:38:39 -0600 Subject: ktest: Enable user input to the console Allow the user to send input to the console by putting the terminal in cbreak mode (to allow reading stdin one character at a time) and copying all stdin data to the console's pty. Link: http://lkml.kernel.org/r/bb1bbe7d202c95a3ce7894cfffdd8c725875978e.1422473610.git.jpoimboe@redhat.com Signed-off-by: Josh Poimboeuf Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 51 +++++++++++++++++++++++++++++++------------- 1 file changed, 36 insertions(+), 15 deletions(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 2d3191693567..ef1d99f3859c 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -178,7 +178,7 @@ my $checkout; my $localversion; my $iteration = 0; my $successes = 0; -my $stty; +my $stty_orig; my $bisect_good; my $bisect_bad; @@ -1458,7 +1458,11 @@ sub open_console { my $pid; # save terminal settings - $stty = `stty -g`; + $stty_orig = `stty -g`; + + # place terminal in cbreak mode so that stdin can be read one character at + # a time without having to wait for a newline + system("stty -icanon -echo -icrnl"); create_pty($ptm, $pts); @@ -1487,7 +1491,7 @@ sub close_console { close($fp); # restore terminal settings - system("stty $stty"); + system("stty $stty_orig"); } sub start_monitor { @@ -1827,7 +1831,9 @@ sub wait_for_input { my ($fp, $time) = @_; my $rin; - my $ready; + my $rout; + my $nr; + my $buf; my $line; my $ch; @@ -1837,21 +1843,36 @@ sub wait_for_input $rin = ''; vec($rin, fileno($fp), 1) = 1; - ($ready, $time) = select($rin, undef, undef, $time); + vec($rin, fileno(\*STDIN), 1) = 1; - $line = ""; + while (1) { + $nr = select($rout=$rin, undef, undef, $time); - # try to read one char at a time - while (sysread $fp, $ch, 1) { - $line .= $ch; - last if ($ch eq "\n"); - } + if ($nr <= 0) { + return undef; + } - if (!length($line)) { - return undef; - } + # copy data from stdin to the console + if (vec($rout, fileno(\*STDIN), 1) == 1) { + sysread(\*STDIN, $buf, 1000); + syswrite($fp, $buf, 1000); + next; + } - return $line; + $line = ""; + + # try to read one char at a time + while (sysread $fp, $ch, 1) { + $line .= $ch; + last if ($ch eq "\n"); + } + + if (!length($line)) { + return undef; + } + + return $line; + } } sub reboot_to { -- cgit v1.2.3-59-g8ed1b From 4bf6e1fc992a19e3a1ce7798df969817467c4360 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Thu, 29 Jan 2015 10:06:07 -0500 Subject: ktest: Print build,install,boot,test times at success and failure Since both success and failure may shortcut and exit ktest, it is better to print the status times there too. Once times are printed, the values for the times are reset, so they will not print more than once. Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index ef1d99f3859c..ca20ce2dc8b6 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -1643,6 +1643,8 @@ sub fail { $name = " ($test_name)"; } + print_times; + doprint "%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%\n"; doprint "%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%\n"; doprint "KTEST RESULT: TEST $i$name Failed: ", @_, "\n"; @@ -2494,6 +2496,8 @@ sub success { $name = " ($test_name)"; } + print_times; + doprint "\n\n*******************************************\n"; doprint "*******************************************\n"; doprint "KTEST RESULT: TEST $i$name SUCCESS!!!! **\n"; -- cgit v1.2.3-59-g8ed1b From 1cb9e64298e9af6b6a8962d43abefdf0b8a635f9 Mon Sep 17 00:00:00 2001 From: Josh Poimboeuf Date: Thu, 29 Jan 2015 20:54:53 -0600 Subject: ktest: Cleanup terminal on dodie() failure If dodie() is called with the console open, restore the terminal's original settings before dying. Link: http://lkml.kernel.org/r/20150130025453.GB20952@treble.redhat.com Signed-off-by: Josh Poimboeuf Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index ca20ce2dc8b6..840803b3cd41 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -1407,6 +1407,11 @@ sub dodie { print " See $opt{LOG_FILE} for more info.\n"; } + if ($monitor_cnt) { + # restore terminal settings + system("stty $stty_orig"); + } + die @_, "\n"; } @@ -1449,7 +1454,7 @@ sub exec_console { close($pts); exec $console or - dodie "Can't open console $console"; + die "Can't open console $console"; } sub open_console { -- cgit v1.2.3-59-g8ed1b From 7c2c49eceb79eb4738f38a00270830057b5bfb76 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" Date: Tue, 3 Feb 2015 15:45:13 -0500 Subject: ktest: Place quotes around item variable Seems that some of the new console logic causes doprint to possibly get evaluated. When printing a commit message that contains parenthesis, it fails with a shell parsing error. This gets fixed when we add quotes around the $item variable, and prevent it from being evaluated by any shell commands. Signed-off-by: Steven Rostedt --- tools/testing/ktest/ktest.pl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/testing/ktest/ktest.pl b/tools/testing/ktest/ktest.pl index 840803b3cd41..d08e214ec6e7 100755 --- a/tools/testing/ktest/ktest.pl +++ b/tools/testing/ktest/ktest.pl @@ -3447,7 +3447,7 @@ sub patchcheck { my $sha1 = $item; $sha1 =~ s/^([[:xdigit:]]+).*/$1/; - doprint "\nProcessing commit $item\n\n"; + doprint "\nProcessing commit \"$item\"\n\n"; run_command "git checkout $sha1" or die "Failed to checkout $sha1"; -- cgit v1.2.3-59-g8ed1b