Bug #44401 mtr daily-basic-tests.DbAsyncGeneratorime_60__1 failed once, but not again...
Submitted: 22 Apr 2009 4:07 Modified: 18 Jun 2009 13:27
Reporter: jack andrews Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Cluster: Cluster (NDB) storage engine Severity:S3 (Non-critical)
Version:mysql-5.1-telco-7.0 OS:Microsoft Windows
Assigned to: jack andrews CPU Architecture:Any

[22 Apr 2009 4:07] jack andrews
Description:
Logging: ./mysql-test-run.pl  --suite=daily-basic-tests --force --retry=0
090407 20:45:59 [Warning] Forcing shutdown of 1 plugins
MySQL Version 5.1.32
Checking supported features...
 - using ndbcluster when necessary, mysqld supports it
 - SSL connections supported
Collecting tests...
vardir: c:/w/repo/70/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory 'c:/w/repo/70/mysql-test/var'...
Installing system database...
Using server port 63792

[snip other test runs prior to DbAG_60__1]
==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 250, with reserved ports 12500..12509
worker[1] mysql-test-run: WARNING: running this script as _root_ will cause some
 tests to be skipped
timer 6588: expired after 900 seconds
worker[1] Trying to dump core for [mysqltest - pid: 7280, winpid: 7280]
worker[1] Trying to dump core for [mysqld.1.1 - pid: 5624, winpid: 5624]
worker[1] Trying to dump core for [ndb_mgmd.1.1 - pid: 3848, winpid: 3848]
worker[1] Trying to dump core for [ndbd.1.1 - pid: 6244, winpid: 6244]
worker[1] Trying to dump core for [ndbd.2.1 - pid: 648, winpid: 648]
daily-basic-tests.DbAsyncGeneratorime_60__1 [ fail ]  timeout after 900 seconds
        Test ended at 2009-04-07 21:02:48

Test case timeout after 900 seconds

 == c:/w/repo/70/mysql-test/var/tmp/analyze-timeout-mysqld.1.1.err ==
SHOW PROCESSLIST;
Id      User    Host    db      Command Time    State   Info
3       root    localhost:63929 NULL    Query   0       NULL    SHOW PROCESSLIST

 - saving 'c:/w/repo/70/mysql-test/var/log/daily-basic-tests.DbAsyncGeneratorime
_60__1/' to 'c:/w/repo/70/mysql-test/var/log/daily-basic-tests.DbAsyncGeneratori
me_60__1/'
result_format: 2

## DbCreate
Using temporary tables
creating table SUBSCRIBER...
retry sleep 70ms on error 702
creating table SUBSCRIBER... done
creating table GROUP_T...
creating table GROUP_T... done
creating table SESSION...
creating table SESSION... done
creating table SERVER...
creating table SERVER... done
Populating 20 'servers' ...
done
Populating 500000 'subscribers' ...
done
Populating 100 'groups' ...
done

NDBT_ProgramExit: 0 - OK

## DbAsyncGenerator -time 60 -p 100

Starting Test with 1 process(es) for 60 sec parallellism 100
   WarmUp/coolDown = 10 sec
Time: 2009-03-07 11:04:47
Waiting for startup to finish

[snip]

but when running ./mysql-test-run.pl --suite=daily-basic-tests --do-test=DbAsyncGeneratorime_60__1
i get no failures -- indicating a previous test smashed something:

How to repeat:
.
[22 Apr 2009 4:24] jack andrews
the original log with failing tests is here:
  http://bugs.mysql.com/bug.php?id=44400

but individually, it passes:

jack@asus /cygdrive/c/w/repo/70/mysql-test
$ ./mysql-test-run.pl --suite=daily-basic-tests --do-test=DbAsyncGeneratorime_6
0__1
Logging: ./mysql-test-run.pl  --suite=daily-basic-tests --do-test=DbAsyncGenerat
orime_60__1
090422 14:04:17 [Warning] Forcing shutdown of 1 plugins
MySQL Version 5.1.32
Checking supported features...
 - using ndbcluster when necessary, mysqld supports it
 - SSL connections supported
Collecting tests...
vardir: c:/w/repo/70/mysql-test/var
Checking leftover processes...
 - found old pid 6232 in 'mysqld.1.1.pid', killing it...
   process did not exist!
Removing old var directory...
Creating var directory 'c:/w/repo/70/mysql-test/var'...
Installing system database...
Using server port 53732

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 250, with reserved ports 12500..12509
worker[1] mysql-test-run: WARNING: running this script as _root_ will cause some
 tests to be skipped
result_format: 2

## DbCreate
Using temporary tables
creating table SUBSCRIBER...
retry sleep 70ms on error 702
creating table SUBSCRIBER... done
creating table GROUP_T...
creating table GROUP_T... done
creating table SESSION...
creating table SESSION... done
creating table SERVER...
creating table SERVER... done
Populating 20 'servers' ...
done
Populating 500000 'subscribers' ...
done
Populating 100 'groups' ...
done

NDBT_ProgramExit: 0 - OK

## DbAsyncGenerator -time 60 -p 1

Starting Test with 1 process(es) for 60 sec parallellism 1
   WarmUp/coolDown = 10 sec
Time: 2009-03-22 04:11:07
Waiting for startup to finish
Benchmark period starts
daily-basic-tests.DbAsyncGeneratorime_60__1 [ pass ]  173778
result_format: 2

## DbCreate
Using temporary tables
creating table SUBSCRIBER... it already exists
creating table GROUP_T... it already exists
creating table SESSION... it already exists
creating table SERVER... it already exists
Populating 20 'servers' ...
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
done
Populating 500000 'subscribers' ...
630: Tuple already existed when attempting to insert
Terminating
## DbAsyncGenerator -time 60 -p 100

Starting Test with 1 process(es) for 60 sec parallellism 100
   WarmUp/coolDown = 10 sec
Time: 2009-03-22 04:11:59
Waiting for startup to finish
Benchmark period starts
Benchmark period done
All threads have finished

------ Test Results ------
Length        : 60 sec
Processor     : asus
Number of Proc: 1
Parallellism  : 100
UseNdbRecord  : 0

  T1: 51016 (25.00%) Latency(ms) avg: 19 min: 4 max: 57 std: 6 n: 399
  T2: 50981 (24.98%) Latency(ms) avg: 13 min: 0 max: 58 std: 8 n: 397
  T3: 40830 (20.01%) Latency(ms) avg: 38 min: 1 max: 92 std: 13 n: 322
      Branches Executed: 33312 (81.59%)
  T4: 30629 (15.01%) Latency(ms) avg: 41 min: 15 max: 95 std: 13 n: 237
      Branches Executed: 27485 (89.74%)
      Rollback Executed: 612 (2.00%)
  T5: 30591 (14.99%) Latency(ms) avg: 41 min: 19 max: 91 std: 11 n: 239
      Branches Executed: 27170 (88.82%)
      Rollback Executed: 616 (2.01%)

  Overall Statistics:
     Transactions: 204047
     Outer       : 3401 TPS

NDBT_ProgramExit: 0 - OK

daily-basic-tests.DbAsyncGeneratorime_60__100 [ pass ]  87208
result_format: 2

## DbCreate
Using temporary tables
creating table SUBSCRIBER... it already exists
creating table GROUP_T... it already exists
creating table SESSION... it already exists
creating table SERVER... it already exists
Populating 20 'servers' ...
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
630: Tuple already existed when attempting to insert
done
Populating 500000 'subscribers' ...
630: Tuple already existed when attempting to insert
Terminating
## DbAsyncGenerator -time 60 -p 1 -proc 25

Starting Test with 25 process(es) for 60 sec parallellism 1
   WarmUp/coolDown = 10 sec
Time: 2009-03-22 04:13:30
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finishWaiting for startup to finish

Benchmark period startsBenchmark period starts

Waiting for startup to finish
Waiting for startup to finishBenchmark period starts

Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finishWaiting for startup to finish

Benchmark period startsBenchmark period starts

Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Waiting for startup to finish
Benchmark period starts
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
Benchmark period done
All threads have finished

------ Test Results ------
Length        : 60 sec
Processor     : asus
Number of Proc: 25
Parallellism  : 1
UseNdbRecord  : 0

  T1: 39170 (24.99%) Latency(ms) avg: 5 min: 3 max: 29 std: 2 n: 309
  T2: 39171 (24.99%) Latency(ms) avg: 3 min: 1 max: 14 std: 1 n: 308
  T3: 31346 (20.00%) Latency(ms) avg: 13 min: 9 max: 30 std: 2 n: 244
      Branches Executed: 25937 (82.74%)
  T4: 23520 (15.01%) Latency(ms) avg: 14 min: 10 max: 42 std: 3 n: 185
      Branches Executed: 21237 (90.29%)
      Rollback Executed: 474 (2.02%)
  T5: 23519 (15.01%) Latency(ms) avg: 14 min: 10 max: 34 std: 3 n: 184
      Branches Executed: 21148 (89.92%)
      Rollback Executed: 469 (1.99%)

  Overall Statistics:
     Transactions: 156726
     Outer       : 2612 TPS

NDBT_ProgramExit: 0 - OK

daily-basic-tests.DbAsyncGeneratorime_60__1_roc_25 [ pass ]  86268
------------------------------------------------------------
The servers were restarted 0 times
Spent 347.254 of 643 seconds executing testcases

All 3 tests were successful.
[28 Apr 2009 8:41] Magnus BlÄudd
daily-basic-tests.DbAsyncGeneratorime_60__1_roc_25 [ pass ]  86268
                                                             ^^^^^
I guess that "pure luck" saved you this time, since the max value is 90000, isn't it? Anyway it can be increased with --testcase-timeout=<value in minutes> you like.

There is also:
 --max-test-fail=<value|default is 10>
[18 Jun 2009 13:27] jack andrews
more analysis will be done on atrt test suite soon