randgen team mailing list archive

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

Roel,


I have looked briefly into the issue. As in most cases, reducing the test as much as possible helps to understand the issue better. In this case I tried running only a single query with all transformers enabled, and there was a difference of 2 statements (I used the grammar optimizer_no_subquery.yy):

$ grep "transforms" /tmp/test1.log | wc -l
26
$ grep "transforms" /tmp/test1.txt | wc -l
28

Then I did some extra checks with grep, e.g. "grep SELECT", "grep
INSERT", "grep CREATE" added to the command lines above, before the "wc
-l". After quickly inspecting the output with this kind of filtering, it
seemed that something related to triggers was missing, so I re-ran the
test using only the ExecuteAsTrigger transformer
(--transformer=ExecuteAsTrigger). Then I got:

$ grep "transforms" /tmp/test1.log | wc -l
6
$ grep "transforms" /tmp/test1.txt | wc -l
8

With this few statements, manual inspection is feasible. Two statements
were in the general log, but not in the trace:

1)  CREATE DATABASE IF NOT EXISTS transforms

This was the very first statement in the general log which contained the
string "transforms". The trace did not include this, but it had:

/* GenTest::Transform::ExecuteAsTrigger */ CREATE DATABASE IF NOT EXISTS transforms;
which also the general log had.

It turns out that the latter is from the ExecuteAsTrigger transformer
itself, while the fomer (the statement that was missing from the trace)
is from GenTest/Validator/Transformer.pm::validate():

	if ($database_created == 0) {
		$executor->dbh()->do("CREATE DATABASE IF NOT EXISTS transforms");
		$database_created = 1;
	}

Here, the code bypasses the executor code by doing
$executor->dbh()->do() instead of $executor->execute(). So this explains
why it is not included in the trace, as the trace functionality is in
the execute() sub. I do not know why the executor is bypassed like this,
or if it can/should be changed.

I suspect that the code shown above is only executed once per test run,
so it should not contribute that much to a huge difference in counts as
shown in the bug description.


2) INSERT INTO transforms.trigger213329  SELECT    alias2 . `col_time_key` AS field1 , alias1 . `col_varchar_key` AS field2 , alias2 . `col_datetime_key` AS field3 , alias1 . `col_varchar_key` AS field4 , alias2 . `col_int_key` AS field5 FROM ( CC AS alias1 , CC AS alias2 ) WHERE ( alias1 . `pk` > 122 AND alias1 . `pk` < ( 122 + 103 ) OR alias1 . `col_varchar_key`  IN ('USA' , 'm') ) AND ( alias1 . `col_int_nokey` <> alias1 . `col_varchar_nokey` OR alias1 . `col_int_nokey` IS  NULL )  GROUP BY field1, field2, field3, field4, field5  ORDER BY field2 DESC

This statement is also missing from the trace. This statement turns out
to be the action caused by the trigger itself. The trigger definition
looks like this:

CREATE TRIGGER trigger113329 BEFORE INSERT ON trigger113329 FOR EACH ROW
INSERT INTO transforms.trigger213329  SELECT    alias2 . `col_time_key`
AS field1 , alias1 . `col_varchar_key` AS field2 , alias2 .
`col_datetime_key` AS field3 , alias1 . `col_varchar_key` AS field4 ,
alias2 . `col_int_key` AS field5 FROM ( CC AS alias1 , CC AS alias2 )
WHERE ( alias1 . `pk` > 122 AND alias1 . `pk` < ( 122 + 103 ) OR alias1
. `col_varchar_key`  IN ('USA' , 'm') ) AND ( alias1 . `col_int_nokey`
<> alias1 . `col_varchar_nokey` OR alias1 . `col_int_nokey` IS  NULL )
GROUP BY field1, field2, field3, field4, field5  ORDER BY field2 DESC

In other words, "before each insert into trigger113329 do an insert into
transforms.trigger213329". This is reflected in the general log, but, as
it happens only on the server side, it is not reflected in the RQG
trace.


Similarly, we will see that e.g. prepared statements have more "footprint" in the general log than in the RQG trace. For example,

EXECUTE prep_stmt_13655 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */;

in the RQG sql trace results in

9 Query  EXECUTE prep_stmt_13655 /* TRANSFORM_OUTCOME_UNORDERED_MATCH */
9 Execute        SELECT    alias2 . `col_time_key` AS field1 , alias1 . `col_varchar_key` AS field2 , alias2 . `col_datetime_key` AS field3 , alias1 . `col_varchar_key` AS field4 , alias2 . `col_int_key` AS field5 FROM ( CC AS alias1 , CC AS alias2 ) WHERE ( alias1 . `pk` > 122 AND alias1 . `pk` < ( 122 + 103 ) OR alias1 . `col_varchar_key`  IN ('USA' , 'm') ) AND ( alias1 . `col_int_nokey` <> alias1 . `col_varchar_nokey` OR alias1 . `col_int_nokey` IS  NULL )  GROUP BY field1, field2, field3, field4, field5  ORDER BY field2 DESC

in the general log. There was no difference in "transforms" counts i
this latter example, but there may be other situations where the count
will be different yet valid.

That said, when I did a run with --queries=1000 and all transformers
enabled, I got:

$ grep "transforms" /tmp/test1.log | grep -v "trigger" | wc -l
17274
$ grep "transforms" /tmp/test1.txt | grep -v "trigger" | wc -l
17275

and this difference of 1 is explained by 1) above.

Based on what I know at this point I would recommend closing this bug as
"Not a bug". But I will leave some time for further feedback or new
evidence, in case I missed something.

-- 
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