Well, that’s pretty much it, thanks for stopping by ; )

In all seriousness, it’s kind of neat that we’re using dbqp to run some of our staging tests and we gain a few neat things:

Speed

Here are the trend charts for randgen and crashme.  While it doesn’t look like randgen is showing much of an improvement, it is worth mentioning that this job now runs both the standard and the transaction log tests in a single run >: )  Previously, we had a separate drizzle-automation job for the transaction log.  Just the trx_log tests took ~30 minutes to run (plus build time).  Long story short, we’re saving about 30-40 minutes on randgen testing per staging run and only needing to build once!

Maintainability

The jobs we run are in the tree and anyone can easily repeat them.  While Drizzle-automation kicks major butt (and I have taken many ideas from it), it is a separate piece of software that requires setup and maintenance.  Basing things around an in-tree setup means that you only need the code and any required bits and pieces.  Now if we need to set up a new randgen machine, we only need the randgen and dbd::drizzle installed (and we plan on including randgen in-tree soon, so you won’t even need that!).  If we need to set up a new crash-me machine, we only need dbd::drizzle – and everyone should have dbd::drizzle installed! ; )

Ease of use

Pretty much all tests provide the same standard output:

dtr mode

From the command:

./dbqp

Our default mode is dtr (aka using drizzletest.cc to execute standard .test files). To run all available tests, use the make target – make test-dbqp

20110621-081404  trigger_dictionary.loaded                  [ pass ]       43
20110621-081408  logging_stats.cumulative                   [ pass ]     1045
20110621-081412  errmsg_stderr.stderr                       [ pass ]       36
20110621-081412  ===============================================================
20110621-081412 INFO Test execution complete in 496 seconds
20110621-081412 INFO Summary report:
20110621-081412 INFO Executed 566/566 test cases, 100.00 percent
20110621-081412 INFO STATUS: PASS, 566/566 test cases, 100.00 percent executed
20110621-081412 INFO Spent 254 / 496 seconds on: TEST(s)
20110621-081412 INFO Test execution complete
20110621-081412 INFO Stopping all running servers...


randgen mode

From the command:

./dbqp --mode=randgen --randgen-path=/path/to/your/randgen


20110621-170141  main.subquery                              [ pass ]     3780
20110621-170148  main.subquery_semijoin                     [ pass ]     3016
20110621-170156  main.subquery_semijoin_nested              [ pass ]     3750
20110621-170202  main.varchar                               [ pass ]     2658
20110621-170202  ===============================================================
20110621-170202 INFO Test execution complete in 147 seconds
20110621-170202 INFO Summary report:
20110621-170202 INFO Executed 19/19 test cases, 100.00 percent
20110621-170202 INFO STATUS: PASS, 19/19 test cases, 100.00 percent executed
20110621-170202 INFO Spent 77 / 147 seconds on: TEST(s)
20110621-170202 INFO Test execution complete
20110621-170202 INFO Stopping all running servers...


crashme mode

From the command:

./dbqp --mode=crashme


20110621-181515  main.crashme                               [ fail ]   149840
20110621-181515  func_extra_to_days=error        # Function TO_DAYS
20110621-181515  ###
20110621-181515  ###<select to_days('1996-01-01') from crash_me_d
20110621-181515  ###>2450084
20110621-181515  ###We expected '729024' but got '2450084'
20110621-181515  func_odbc_timestampadd=error        # Function TIMESTAMPADD
20110621-181515  ###
20110621-181515  ###<select timestampadd(SQL_TSI_SECOND,1,'1997-01-01 00:00:00')
20110621-181515  ###>1997-01-01 00:00:01.000000
20110621-181515  ###We expected '1997-01-01 00:00:01' but got '1997-01-01 00:00:01.000000'
20110621-181515  ###
20110621-181515  ###<select {fn timestampadd(SQL_TSI_SECOND,1,{ts '1997-01-01 00:00:00'}) }
20110621-181515  ###>1997-01-01 00:00:01.000000
20110621-181515  ###We expected '1997-01-01 00:00:01' but got '1997-01-01 00:00:01.000000'
20110621-181515
20110621-181515 ERROR Failed test.  Use --force to execute beyond the first test failure
20110621-181515  ===============================================================
20110621-181515 INFO Test execution complete in 153 seconds
20110621-181515 INFO Summary report:
20110621-181515 INFO Executed 1/1 test cases, 100.00 percent
20110621-181515 INFO STATUS: FAIL, 1/1 test cases, 100.00 percent executed
20110621-181515 INFO FAIL tests: main.crashme
20110621-181515 INFO Spent 149 / 153 seconds on: TEST(s)
20110621-181515 INFO Test execution complete
20110621-181515 INFO Stopping all running servers...


While this isn’t a huge feature, it is nice to have a standardized report for knowing if something failed, what failed and how (we always dump test tool output on test failures).  Why is this nice?  Well, the world is a busy place and only needing to know one way of reading test output simplifies things just a teensy little bit.  This small improvement becomes a huge benefit over time if you happen to spend good chunks of your day looking at test output like me : )

Other than that, I’m still working on teaching dbqp interesting new tricks that will help me in testing SkySQL‘s Reference Architecture – expect to hear more about that next month!

One of the long term testing goals for Drizzle is to move all of our test logic directly in-tree.  Currently, we use a system called drizzle-automation to execute a variety of tests for our staging branch.  This is the final set of tests patches must pass before being allowed to merge into Drizzle trunk and includes things like sysbench, dbt2, the randgen, etc.  With the development of dbqp, we can now move this testing logic directly into the tree (and even move some of the testing tools there as well).  Of course, I’ve rambled on about this before, but I personally think it is cool and useful ; )  However enough of the sales pitch, on to the new modes!

sysbench mode

With but a simple incantation of ./dbqp –mode=sysbench [–suite=readonly|readwrite], you too can invoke the mighty sysbench configurations that we use to ensure each and every Drizzle patch is worth its salt!

Basically, each test case is a sysbench command line for a certain concurrency:


sysbench --max-time=240 --max-requests=0 --test=oltp --db-ps-mode=disable --drizzle-table-engine=innodb --oltp-read-only=off --oltp-table-size=1000000 --drizzle-mysql=on --drizzle-user=root --drizzle-db=test --drizzle-port=$MASTER_MYPORT --drizzle-host=localhost --db-driver=drizzle --num-threads=32

readonly and readwrite suites differ only with the –oltp-read-only switch being on|off.

The output looks like this (at present):

20110601-191706  ===============================================================
20110601-191706  TEST NAME                                  [ RESULT ] TIME (ms)
20110601-191706  ===============================================================
20110601-191706  readonly.concurrency_16                    [ pass ]   240019
20110601-191706  max_req_lat_ms: 21.44
20110601-191706  rwreqps: 4208.2
20110601-191706  min_req_lat_ms: 6.31
20110601-191706  deadlocksps: 0.0
20110601-191706  tps: 150.29
20110601-191706  avg_req_lat_ms: 6.65
20110601-191706  95p_req_lat_ms: 7.02
20110601-191706  ===============================================================
20110601-191706 INFO Test execution complete in 275 seconds
20110601-191706 INFO Summary report:
20110601-191706 INFO Executed 1/1 test cases, 100.00 percent
20110601-191706 INFO STATUS: PASS, 1/1 test cases, 100.00 percent executed
20110601-191706 INFO Spent 240 / 275 seconds on: TEST(s)
20110601-191706 INFO Test execution complete
20110601-191706 INFO Stopping all running servers...


This is probably the most ‘work-in-progress’ mode we have.  The reason for this is that our Jenkins system uses a database of previous results for comparison / emailing and we need to come up with some way to keep this bit working properly.  I’m still collaborating with the mighty computing wizard Monty Taylor on this.  One of the possibilities we’ve discussed is the use of the Phoronix Test Suite.  Personally, I think this looks pretty interesting / promising and if any php gurus want to assist here, we will compose ballads to honor your awesomeness.

sqlbench mode

Technically, sqlbench and crashme modes are both tied to the sql-bench test suite, however, they do different things and produce different output, so I will discuss them separately.

The biggest thing to note is that sql-bench is now in-tree.  You can read a bit more about this tool here and here

This mode basically calls the run-all-tests sql-bench script.  This executes all of the available tests for sql-bench and reports on the results (dbqp will fail if any sql-bench tests does).  NOTE – this takes some time (~45 minutes on my laptop)

To use it:
./dbqp –mode=sqlbench

Output:

20110608-135645  ===============================================================
20110608-135645  TEST NAME                                  [ RESULT ] TIME (ms)
20110608-135645  ===============================================================
20110608-135645  main.all_sqlbench_tests                    [ pass ]  2732007
20110608-135645  Test finished. You can find the result in:
20110608-135645  drizzle/tests/workdir/RUN-drizzle-Linux_2.6.38_9_generic_x86_64
20110608-135645  Benchmark DBD suite: 2.15
20110608-135645  Date of test:        2011-06-08 13:11:10
20110608-135645  Running tests on:    Linux 2.6.38-9-generic x86_64
20110608-135645  Arguments:           --connect-options=port=9306 --create-options=ENGINE=innodb
20110608-135645  Comments:
20110608-135645  Limits from:
20110608-135645  Server version:      Drizzle 2011.06.19.2325
20110608-135645  Optimization:        None
20110608-135645  Hardware:
20110608-135645
20110608-135645  alter-table: Total time: 42 wallclock secs ( 0.06 usr  0.04 sys +  0.00 cusr  0.00 csys =  0.10 CPU)
20110608-135645  ATIS: Total time: 22 wallclock secs ( 4.01 usr  0.26 sys +  0.00 cusr  0.00 csys =  4.27 CPU)
20110608-135645  big-tables: Total time: 24 wallclock secs ( 4.16 usr  0.22 sys +  0.00 cusr  0.00 csys =  4.38 CPU)
20110608-135645  connect: Total time: 31 wallclock secs ( 6.81 usr  4.50 sys +  0.00 cusr  0.00 csys = 11.31 CPU)
20110608-135645  create: Total time: 59 wallclock secs ( 2.93 usr  1.65 sys +  0.00 cusr  0.00 csys =  4.58 CPU)
20110608-135645  insert: Total time: 1962 wallclock secs (270.53 usr 66.35 sys +  0.00 cusr  0.00 csys = 336.88 CPU)
20110608-135645  select: Total time: 560 wallclock secs (23.12 usr  4.62 sys +  0.00 cusr  0.00 csys = 27.74 CPU)
20110608-135645  transactions: Total time: 21 wallclock secs ( 2.43 usr  1.98 sys +  0.00 cusr  0.00 csys =  4.41 CPU)
20110608-135645  wisconsin: Total time: 10 wallclock secs ( 2.11 usr  0.52 sys +  0.00 cusr  0.00 csys =  2.63 CPU)
20110608-135645
20110608-135645  All 9 test executed successfully
20110608-135645
20110608-135645  Totals per operation:
20110608-135645  Operation             seconds     usr     sys     cpu   tests
20110608-135645  alter_table_add                       18.00    0.02    0.00    0.02     100
20110608-135645  alter_table_drop                      17.00    0.02    0.01    0.03      91
20110608-135645  connect                                2.00    1.02    0.51    1.53    2000
<snip>
20110608-135645  update_rollback                        3.00    0.26    0.23    0.49     100
20110608-135645  update_with_key                       73.00    6.70    5.23   11.93  300000
20110608-135645  update_with_key_prefix                34.00    4.45    2.30    6.75  100000
20110608-135645  wisc_benchmark                         2.00    1.49    0.00    1.49     114
20110608-135645  TOTALS                              2865.00  310.26   79.94  390.20 2974250
20110608-135645
20110608-135645  ===============================================================
20110608-135645 INFO Test execution complete in 2735 seconds
20110608-135645 INFO Summary report:
20110608-135645 INFO Executed 1/1 test cases, 100.00 percent
20110608-135645 INFO STATUS: PASS, 1/1 test cases, 100.00 percent executed
20110608-135645 INFO Spent 2732 / 2735 seconds on: TEST(s)
20110608-135645 INFO Test execution complete
20110608-135645 INFO Stopping all running servers...


crashme mode

This mode is also provided thanks to the sql-bench suite, but the output and processing are different, thus a separate mode and section : )

Anyway, there is a script called crash-me that is provided with sql-bench.  We execute this script, look for any test failures in the output and report pass/fail.

There is an interesting story around these tests (and the sample output)- our Jenkins crashme slave has been down / having problems for a while.  Due to life and whatnot, we’ve had some issues getting it sorted.  However, once I got this mode up and running, I discovered that we were failing some tests:

20110608-152759  ===============================================================
20110608-152759  TEST NAME                                  [ RESULT ] TIME (ms)
20110608-152759  ===============================================================
20110608-152759  main.crashme                               [ fail ]   155298
20110608-152759  func_extra_to_days=error           # Function TO_DAYS
20110608-152759  ###
20110608-152759  ###<select to_days('1996-01-01') from crash_me_d
20110608-152759  ###>2450084
20110608-152759  ###We expected '729024' but got '2450084'
20110608-152759  func_odbc_timestampadd=error               # Function TIMESTAMPADD
20110608-152759  ###
20110608-152759  ###<select timestampadd(SQL_TSI_SECOND,1,'1997-01-01 00:00:00')
20110608-152759  ###>1997-01-01 00:00:01.000000
20110608-152759  ###We expected '1997-01-01 00:00:01' but got '1997-01-01 00:00:01.000000'
20110608-152759  ###
20110608-152759  ###<select {fn timestampadd(SQL_TSI_SECOND,1,{ts '1997-01-01 00:00:00'}) }
20110608-152759  ###>1997-01-01 00:00:01.000000
20110608-152759  ###We expected '1997-01-01 00:00:01' but got '1997-01-01 00:00:01.000000'
20110608-152759
20110608-152759 ERROR Failed test.  Use --force to execute beyond the first test failure
20110608-152759  ===============================================================
20110608-152759 INFO Test execution complete in 158 seconds
20110608-152759 INFO Summary report:
20110608-152759 INFO Executed 1/1 test cases, 100.00 percent
20110608-152759 INFO STATUS: FAIL, 1/1 test cases, 100.00 percent executed
20110608-152759 INFO FAIL tests: main.crashme
20110608-152759 INFO Spent 155 / 158 seconds on: TEST(s)
20110608-152759 INFO Test execution complete


So, while our tests were down, an ugly bug crept into the works.  Of course, it is terrible that we have a bug, but we can always bzrfind our way to the culprit code (expect a mode for that soon!) and we see the value of constant testing!  At any rate, we can now get our Jenkins slave back in working order and any developer or user that wants to stress their server now has an easy way to do so : )

Upcoming work

I’ve also been doing some cleaning up / reorganizing of dbqp code to allow for other neat tricks.  These changes will enable it to run other servers such as MySQL and allow it to serve as the basis of test suites for tools like mydumper and xtrabackup – I’ve already been discussing things with Stewart and Andrew about this and will be blogging / demoing the code very soon.

Additionally, we’re going to also see about moving the randgen into the Drizzle tree.  We use it for a significant portion of our testing and through the magic of bzr join, it will be easy to provide this tool for everyone (provided they have dbd::drizzle installed, of course).  Stewart was kind enough to set up an initial tree, I’ve just been too busy with SkySQL work to get it done this week.

Finally, we’re still moving forward with making dbqp *the* Drizzle test runner.  This is naturally happening in baby steps, but expect to see some changes in the next month or so.

With that said, I hope that people will enjoy playing with the new toys and I look forward to providing more fun ways of making your favorite dbms sweat in the near future >: )