mtr_report.pm 10.4 KB
Newer Older
kent@mysql.com's avatar
kent@mysql.com committed
1
# -*- cperl -*-
Luis Soares's avatar
Luis Soares committed
2
# Copyright 2004-2008 MySQL AB, 2008 Sun Microsystems, Inc.
3 4 5 6 7 8 9 10 11 12 13 14 15
# 
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License.
# 
# 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 more details.
# 
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
kent@mysql.com's avatar
kent@mysql.com committed
16 17 18 19 20

# This is a library file used by the Perl version of mysql-test-run,
# and is part of the translation of the Bourne shell script with the
# same name.

21
package mtr_report;
kent@mysql.com's avatar
kent@mysql.com committed
22
use strict;
23 24 25 26 27 28

use base qw(Exporter);
our @EXPORT= qw(report_option mtr_print_line mtr_print_thick_line
		mtr_print_header mtr_report mtr_report_stats
		mtr_warning mtr_error mtr_debug mtr_verbose
		mtr_verbose_restart mtr_report_test_passed
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
29
		mtr_report_test_skipped mtr_print
30
		mtr_report_test);
31

32
use mtr_match;
33
require "mtr_io.pl";
kent@mysql.com's avatar
kent@mysql.com committed
34

35 36
my $tot_real_time= 0;

Magnus Svensson's avatar
Magnus Svensson committed
37
our $timestamp= 0;
38
our $timediff= 0;
39 40 41
our $name;
our $verbose;
our $verbose_restart= 0;
42
our $timer= 1;
43

44 45
sub report_option {
  my ($opt, $value)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
46

47 48 49
  # Evaluate $opt as string to use "Getopt::Long::Callback legacy API"
  my $opt_name = "$opt";

50
  # Convert - to _ in option name
51
  $opt_name =~ s/-/_/g;
52
  no strict 'refs';
53
  ${$opt_name}= $value;
54
}
kent@mysql.com's avatar
kent@mysql.com committed
55

56 57 58
sub _name {
  return $name ? $name." " : undef;
}
59 60

sub _mtr_report_test_name ($) {
kent@mysql.com's avatar
kent@mysql.com committed
61
  my $tinfo= shift;
62
  my $tname= $tinfo->{name};
kent@mysql.com's avatar
kent@mysql.com committed
63

64 65
  return unless defined $verbose;

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
66
  # Add combination name if any
67 68 69
  $tname.= " '$tinfo->{combination}'"
    if defined $tinfo->{combination};

70
  print _name(), _timestamp();
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
71
  printf "%-40s ", $tname;
kent@mysql.com's avatar
kent@mysql.com committed
72 73
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
74

kent@mysql.com's avatar
kent@mysql.com committed
75
sub mtr_report_test_skipped ($) {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
76
  my ($tinfo)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
77
  $tinfo->{'result'}= 'MTR_RES_SKIPPED';
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
78 79

  mtr_report_test($tinfo);
80 81 82
}


83 84
sub mtr_report_test_passed ($) {
  my ($tinfo)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
85

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
86
  # Save the timer value
87 88
  my $timer_str=  "";
  if ( $timer and -f "$::opt_vardir/log/timer" )
kent@mysql.com's avatar
kent@mysql.com committed
89
  {
90 91
    $timer_str= mtr_fromfile("$::opt_vardir/log/timer");
    $tinfo->{timer}= $timer_str;
kent@mysql.com's avatar
kent@mysql.com committed
92
  }
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
93

Magnus Svensson's avatar
Magnus Svensson committed
94 95 96 97
  # Big warning if status already set
  if ( $tinfo->{'result'} ){
    mtr_warning("mtr_report_test_passed: Test result",
		"already set to '", $tinfo->{'result'}, ",");
98
  }
99

Magnus Svensson's avatar
Magnus Svensson committed
100 101
  $tinfo->{'result'}= 'MTR_RES_PASSED';

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
102
  mtr_report_test($tinfo);
kent@mysql.com's avatar
kent@mysql.com committed
103 104
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
105

106 107 108 109
sub mtr_report_test ($) {
  my ($tinfo)= @_;
  _mtr_report_test_name($tinfo);

110 111 112 113
  my $comment=  $tinfo->{'comment'};
  my $logfile=  $tinfo->{'logfile'};
  my $warnings= $tinfo->{'warnings'};
  my $result=   $tinfo->{'result'};
114

115 116
  if ($result eq 'MTR_RES_FAILED'){

117 118
    my $timest = format_time();

119
    if ( $warnings )
120
    {
Magnus Svensson's avatar
Magnus Svensson committed
121
      mtr_report("[ fail ]  Found warnings/errors in server log file!");
122
      mtr_report("        Test ended at $timest");
123
      mtr_report($warnings);
124 125
      return;
    }
126 127
    my $timeout= $tinfo->{'timeout'};
    if ( $timeout )
128
    {
129 130
      mtr_report("[ fail ]  timeout after $timeout seconds");
      mtr_report("        Test ended at $timest");
131
      mtr_report("\n$tinfo->{'comment'}");
132 133 134 135
      return;
    }
    else
    {
136
      mtr_report("[ fail ]\n        Test ended at $timest");
137 138
    }

139 140 141 142 143 144 145
    if ( $logfile )
    {
      # Test failure was detected by test tool and its report
      # about what failed has been saved to file. Display the report.
      mtr_report("\n$logfile\n");
    }
    if ( $comment )
146 147 148 149
    {
      # The test failure has been detected by mysql-test-run.pl
      # when starting the servers or due to other error, the reason for
      # failing the test is saved in "comment"
150
      mtr_report("\n$comment\n");
151 152
    }

153
    if ( !$logfile and !$comment )
154 155 156
    {
      # Neither this script or the test tool has recorded info
      # about why the test has failed. Should be debugged.
157
      mtr_report("\nUnknown result, neither 'comment' or 'logfile' set");
158 159
    }
  }
160
  elsif ($result eq 'MTR_RES_SKIPPED')
161 162 163
  {
    if ( $tinfo->{'disable'} )
    {
164
      mtr_report("[ disabled ]  $comment");
165
    }
166
    elsif ( $comment )
167 168 169
    {
      if ( $tinfo->{skip_detected_by_test} )
      {
170
	mtr_report("[ skip ]. $comment");
171 172 173
      }
      else
      {
174
	mtr_report("[ skip ]  $comment");
175 176 177 178 179 180 181
      }
    }
    else
    {
      mtr_report("[ skip ]");
    }
  }
182
  elsif ($result eq 'MTR_RES_PASSED')
183
  {
184 185
    my $timer_str= $tinfo->{timer} || "";
    $tot_real_time += ($timer_str/1000);
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
186
    mtr_report("[ pass ] ", sprintf("%5s", $timer_str));
187 188 189 190 191 192

    # Show any problems check-testcase found
    if ( defined $tinfo->{'check'} )
    {
      mtr_report($tinfo->{'check'});
    }
193 194 195 196
  }
}


kent@mysql.com's avatar
kent@mysql.com committed
197 198 199 200 201 202 203 204 205 206 207
sub mtr_report_stats ($) {
  my $tests= shift;

  # ----------------------------------------------------------------------
  # Find out how we where doing
  # ----------------------------------------------------------------------

  my $tot_skiped= 0;
  my $tot_passed= 0;
  my $tot_failed= 0;
  my $tot_tests=  0;
208
  my $tot_restarts= 0;
209
  my $found_problems= 0;
kent@mysql.com's avatar
kent@mysql.com committed
210 211 212

  foreach my $tinfo (@$tests)
  {
213
    if ( $tinfo->{failures} )
kent@mysql.com's avatar
kent@mysql.com committed
214
    {
215 216 217 218 219 220 221
      # Test has failed at least one time
      $tot_tests++;
      $tot_failed++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' )
    {
      # Test was skipped
kent@mysql.com's avatar
kent@mysql.com committed
222 223 224 225
      $tot_skiped++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' )
    {
226
      # Test passed
kent@mysql.com's avatar
kent@mysql.com committed
227 228 229
      $tot_tests++;
      $tot_passed++;
    }
230

231 232
    if ( $tinfo->{'restarted'} )
    {
233
      # Servers was restarted
234 235
      $tot_restarts++;
    }
236 237 238 239 240 241 242 243 244 245

    # Look for warnings produced by mysqltest
    my $base_file= mtr_match_extension($tinfo->{'result_file'},
				       "result"); # Trim extension
    my $warning_file= "$base_file.warnings";
    if ( -f $warning_file )
    {
      $found_problems= 1;
      mtr_warning("Check myqltest warnings in '$warning_file'");
    }
kent@mysql.com's avatar
kent@mysql.com committed
246 247 248 249 250
  }

  # ----------------------------------------------------------------------
  # Print out a summary report to screen
  # ----------------------------------------------------------------------
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
251
  print "The servers were restarted $tot_restarts times\n";
252

253
  if ( $timer )
254
  {
255 256 257 258
    use English;

    mtr_report("Spent", sprintf("%.3f", $tot_real_time),"of",
	       time - $BASETIME, "seconds executing testcases");
259
  }
kent@mysql.com's avatar
kent@mysql.com committed
260 261


262 263
  my $warnlog= "$::opt_vardir/log/warnings";
  if ( -f $warnlog )
kent@mysql.com's avatar
kent@mysql.com committed
264
  {
265 266
    mtr_warning("Got errors/warnings while running tests, please examine",
		"'$warnlog' for details.");
Luis Soares's avatar
Luis Soares committed
267
 }
kent@mysql.com's avatar
kent@mysql.com committed
268 269 270

  print "\n";

271 272 273
  # Print a list of check_testcases that failed(if any)
  if ( $::opt_check_testcases )
  {
274
    my %check_testcases;
275 276 277 278 279

    foreach my $tinfo (@$tests)
    {
      if ( defined $tinfo->{'check_testcase_failed'} )
      {
280
	$check_testcases{$tinfo->{'name'}}= 1;
281 282 283
      }
    }

284
    if ( keys %check_testcases )
285 286
    {
      print "Check of testcase failed for: ";
287
      print join(" ", keys %check_testcases);
288 289
      print "\n\n";
    }
290
  }
291

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
292 293 294
  # Print a list of testcases that failed
  if ( $tot_failed != 0 )
  {
295 296 297

    # Print each failed test, again
    #foreach my $test ( @$tests ){
298
    #  if ( $test->{failures} ) {
299 300 301 302
    #    mtr_report_test($test);
    #  }
    #}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
303 304 305 306 307 308 309 310 311
    my $ratio=  $tot_passed * 100 / $tot_tests;
    print "Failed $tot_failed/$tot_tests tests, ";
    printf("%.2f", $ratio);
    print "\% were successful.\n\n";

    # Print the list of test that failed in a format
    # that can be copy pasted to rerun only failing tests
    print "Failing test(s):";

312
    my %seen= ();
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
313 314
    foreach my $tinfo (@$tests)
    {
315
      my $tname= $tinfo->{'name'};
316
      if ( $tinfo->{failures} and ! $seen{$tname})
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
317
      {
318 319
        print " $tname";
	$seen{$tname}= 1;
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
320 321 322 323 324 325 326 327 328 329 330 331 332 333
      }
    }
    print "\n\n";

    # Print info about reporting the error
    print
      "The log files in var/log may give you some hint of what went wrong.\n\n",
      "If you want to report this error, please read first ",
      "the documentation\n",
      "at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html\n\n";

   }
  else
  {
334
    print "All $tot_tests tests were successful.\n\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
335 336
  }

337 338
  if ( $tot_failed != 0 || $found_problems)
  {
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
339
    mtr_error("there were failing test cases");
kent@mysql.com's avatar
kent@mysql.com committed
340 341 342
  }
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
343

kent@mysql.com's avatar
kent@mysql.com committed
344 345 346 347 348 349 350
##############################################################################
#
#  Text formatting
#
##############################################################################

sub mtr_print_line () {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
351
  print '-' x 60, "\n";
kent@mysql.com's avatar
kent@mysql.com committed
352 353
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
354

355
sub mtr_print_thick_line {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
356 357
  my $char= shift || '=';
  print $char x 60, "\n";
kent@mysql.com's avatar
kent@mysql.com committed
358 359
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
360

kent@mysql.com's avatar
kent@mysql.com committed
361 362
sub mtr_print_header () {
  print "\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
363 364 365 366 367
  printf "TEST";
  print " " x 38;
  print "RESULT   ";
  print "TIME (ms)" if $timer;
  print "\n";
kent@mysql.com's avatar
kent@mysql.com committed
368 369 370 371 372 373 374
  mtr_print_line();
  print "\n";
}


##############################################################################
#
375
#  Log and reporting functions
kent@mysql.com's avatar
kent@mysql.com committed
376 377 378
#
##############################################################################

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
379
use Time::localtime;
380

381 382
use Time::HiRes qw(gettimeofday);

383 384 385 386 387 388 389
sub format_time {
  my $tm= localtime();
  return sprintf("%4d-%02d-%02d %02d:%02d:%02d",
		 $tm->year + 1900, $tm->mon+1, $tm->mday,
		 $tm->hour, $tm->min, $tm->sec);
}

390 391
my $t0= gettimeofday();

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
392
sub _timestamp {
393
  return "" unless $timestamp;
394

395 396 397 398 399 400 401 402 403 404 405 406
  my $diff;
  if ($timediff){
    my $t1= gettimeofday();
    my $elapsed= $t1 - $t0;

    $diff= sprintf(" +%02.3f", $elapsed);

    # Save current time for next lap
    $t0= $t1;

  }

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
407
  my $tm= localtime();
408
  return sprintf("%02d%02d%02d %2d:%02d:%02d%s ",
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
409
		 $tm->year % 100, $tm->mon+1, $tm->mday,
410
		 $tm->hour, $tm->min, $tm->sec, $diff);
411 412
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
413 414
# Always print message to screen
sub mtr_print (@) {
415
  print _name(), join(" ", @_), "\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
416 417
}

418

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
419
# Print message to screen if verbose is defined
kent@mysql.com's avatar
kent@mysql.com committed
420
sub mtr_report (@) {
421 422
  if (defined $verbose)
  {
423
    print _name(), join(" ", @_), "\n";
424
  }
kent@mysql.com's avatar
kent@mysql.com committed
425 426
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
427

428
# Print warning to screen
kent@mysql.com's avatar
kent@mysql.com committed
429
sub mtr_warning (@) {
430
  print STDERR _name(), _timestamp(),
431
    "mysql-test-run: WARNING: ", join(" ", @_), "\n";
kent@mysql.com's avatar
kent@mysql.com committed
432 433 434
}


435
# Print error to screen and then exit
kent@mysql.com's avatar
kent@mysql.com committed
436
sub mtr_error (@) {
437
  print STDERR _name(), _timestamp(),
438
    "mysql-test-run: *** ERROR: ", join(" ", @_), "\n";
439 440 441
  exit(1);
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
442

kent@mysql.com's avatar
kent@mysql.com committed
443
sub mtr_debug (@) {
444
  if ( $verbose > 2 )
kent@mysql.com's avatar
kent@mysql.com committed
445
  {
446
    print STDERR _name(),
447
      _timestamp(), "####: ", join(" ", @_), "\n";
kent@mysql.com's avatar
kent@mysql.com committed
448 449
  }
}
450

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
451

452
sub mtr_verbose (@) {
453
  if ( $verbose )
454
  {
455
    print STDERR _name(), _timestamp(),
456
      "> ",join(" ", @_),"\n";
457 458
  }
}
kent@mysql.com's avatar
kent@mysql.com committed
459

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
460

461 462 463
sub mtr_verbose_restart (@) {
  my ($server, @args)= @_;
  my $proc= $server->{proc};
464
  if ( $verbose_restart )
465
  {
466
    print STDERR _name(),_timestamp(),
467
      "> Restart $proc - ",join(" ", @args),"\n";
468 469 470 471
  }
}


kent@mysql.com's avatar
kent@mysql.com committed
472
1;