randgen team mailing list archive

["John H. Embretsen" <1220975@xxxxxxxxxxxxxxxxxx>]

Roel,

I no longer have the earlier results, but I did a re-run using MySQL 5.6
(I do not have time to set up a completely new environment just for this
bug). It seems there were no "simplifications" during that run (grep
"implif" /tmp/test1.log).

I did another run with --queries=10000 and --duration=1800 and
--grammar=conf/optimizer/optimizer_subquery_semijoin.yy. Results are as
follows:

$ grep "Simplified transformed query" /tmp/test1.log | wc -l
1

$ grep "transforms" /tmp/test1.txt | wc -l
10375

$ grep "transforms" /tmp/test1.log | wc -l
10078

$ grep "transforms" /tmp/test1.txt | grep -v "trigger" | wc -l
8599

$ grep "transforms" /tmp/test1.log | grep -v "trigger" | wc -l
8598

So, it seems that all discrepancies that I see are casued by reasons mentioned in my previous comment (#10) to this bug report.
I do recognize that the difference in numbers that you see seem proportionally higher, but I cannot say if this has a different root cause or not. 

I suggest trying to perform some kind of "divide and conquer" approach (as indicated earlier) to get to the bottom of this. For example:
 - try with different grammars
 - try filtering out all trigger queries
 - try using a reduced set of Transformers
 - try with fewer queries
 - eliminate unnecessary complexities, such as reporters, multiple threads, server options, grammar masking, etc.

A quick look in the code suggests that the query executions done by the
simplifier for failing transforms should also count in the sqltrace, as
the executors are used directly, but I have not verified this 100%.

-- 
You received this bug notification because you are a member of Random
Query Generator Team, which is subscribed to Random Query Generator.
https://bugs.launchpad.net/bugs/1220975

Title:
  Any logging code in MySQL.pm (--sqltrace or otherwise) does not log
  all transformer queries to the RQG log

Status in SQL Generator for testing SQL servers (MySQL, JavaDB, PostgreSQL):
  Confirmed

Bug description:
  The --sqltrace function does not correctly log all queries which were
  executed against mysqld to the RQG log. The difference seems to be in
  the transformed queries. Some are logged, some are not. Issue is easy
  to reproduce as described below.

  In the example below, sqltrace output goes to /tmp/test1.log, log file
  output goes to /tmp/test1.txt

  [roel@qaserver rqg]$ cat .bzr/branch/last-revision
  893 roel.vandepaar@xxxxxxxxxxx-20130905011549-8w9d4xejwoovmhi6
  [roel@qaserver rqg]$ cat test1
  ps -ef | grep 'test1' | grep -v grep | awk '{print $2}' | xargs sudo kill -9 > /dev/null 2>&1
  rm -Rf /tmp/test1
  mkdir /tmp/test1
  cd /ssd/rqg
  bash -c "set -o pipefail; perl /ssd/rqg/runall.pl --queries=100000000 --seed=24433 --duration=900 --querytimeout=60 --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=FILE --mysqld=--general_log_file=/tmp/test1.txt --sqltrace --threads=25 --mysqld=--innodb_file_per_table=1 --validator=Transformer --mysqld=--innodb_adaptive_hash_index_partitions=1 --basedir=/ssd/Percona-Server-5.5.32-rel31.0-564-debug.Linux.x86_64 --grammar=test1.yy --gendata=conf/examples/example.zz --mtr-build-thread=786 --mask=48291 --vardir1=/tmp/test1 > /tmp/test1.log 2>&1"
  tail -n1 /tmp/test1.log
  [roel@qaserver rqg]$ ./test1
  2013-09-05T11:36:25 [21726] /ssd/rqg/runall.pl will exit with exit status STATUS_SERVER_CRASHED (101)   <--- status outcome is not important I think (it also happens with STATUS_ENVIRONMENT_FAILURE for example)
  [roel@qaserver rqg]$ grep "transforms" /tmp/test1.txt | wc -l
  4607
  [roel@qaserver rqg]$ grep "transforms" /tmp/test1.log | wc -l
  1054
  [roel@qaserver rqg]$ grep "transforms.insert_select" /tmp/test1.txt | wc -l
  1925
  [roel@qaserver rqg]$ grep "transforms.insert_select" /tmp/test1.log | wc -l
  457
  [roel@qaserver rqg]$ grep "transforms.insert_select_15171" /tmp/test1.txt
                     10 Query     DROP TABLE IF EXISTS transforms.insert_select_15171
                     10 Query     CREATE TABLE transforms.insert_select_15171 SELECT GET_LOCK('LOCK', 65535)
                     10 Query     SELECT * FROM transforms.insert_select_15171 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */
                     10 Query     DELETE FROM transforms.insert_select_15171
                     10 Query     INSERT INTO transforms.insert_select_15171 SELECT GET_LOCK('LOCK', 65535)
                     10 Query     SELECT * FROM transforms.insert_select_15171 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */
                     10 Query     DELETE FROM transforms.insert_select_15171
                     10 Query     REPLACE INTO transforms.insert_select_15171 SELECT GET_LOCK('LOCK', 65535)
                     10 Query     SELECT * FROM transforms.insert_select_15171 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */
                     10 Query     DROP TABLE transforms.insert_select_15171
  [roel@qaserver rqg]$ grep "transforms.insert_select_15171" /tmp/test1.log
  [roel@qaserver rqg]$

  This is likely reproducible on any MySQL version, but in this case I
  used Percona Server (lp:percona-server/5.5) at revid 564
  laurynas.biveinis@xxxxxxxxxxx-20130823073534-jcx7aq9dqmpg87zt - the
  issue is consistently reproducible on it. If needbe, this server can
  easily be build by using the lp:percona-qa/build_percona.sh script and
  using the debug version. (i.e. bzr branch lp:percona-server/5.5 -> bzr
  branch lp:percona-qa -> go to 5.5 directory -> call percona-
  qa/build_percona.sh script with no options -> move resulting debug
  build to location of choice after doing cd ..)

To manage notifications about this bug go to:
https://bugs.launchpad.net/randgen/+bug/1220975/+subscriptions