MySQL Bugs: #43801: mysql.test takes too long, fails due to expired timeout on debx86-b in PB

Bug #43801	mysql.test takes too long, fails due to expired timeout on debx86-b in PB
Submitted:	23 Mar 2009 10:08	Modified:	13 Apr 2009 15:20
Reporter:	Alexey Kopytov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Tests: Server	Severity:	S3 (Non-critical)
Version:	5.0, 5.1, 6.0	OS:	Any
Assigned to:	Alexey Kopytov	CPU Architecture:	Any

Description:
mysql.test started to fail due to expired timeout on debx86-b after the test case for bug #41486 has been added: http://tinyurl.com/dlsgow

According to the backlog the server is killed in memset() while logging the following query to the general log:

INSERT INTO t1 SELECT REPEAT('1', 2*1024*1024);

The query takes a few seconds on my laptop, so it could add a significant time to (already long) mysql.test execution especially on a machine which is low on resources.

How to repeat:
Examine mysql.test failures here: http://tinyurl.com/dlsgow

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/70060

2766 Alexey Kopytov	2009-03-23
      Fix for bug #43801: mysql.test takes too long, fails due to 
                          expired timeout on debx86-b in PB 
       
      Moved the resource-intensive test case for bug #41486 into 
      a separate test file to reduce execution time for mysql.test. 
      added:
        mysql-test/r/mysql-bug41486.result
        mysql-test/t/mysql-bug41486.test
      modified:
        mysql-test/r/mysql.result
        mysql-test/t/mysql.test

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/70262

2766 Alexey Kopytov	2009-03-24
      Fix for bug #43801: mysql.test takes too long, fails due to 
                          expired timeout on debx86-b in PB 
      
      Moved the resource-intensive test case for bug #41486 into 
      a separate test file to reduce execution time for mysql.test. 
      added:
        mysql-test/include/wait_until_disconnected.inc
        mysql-test/r/mysql-bug41486.result
        mysql-test/t/mysql-bug41486.test
      modified:
        mysql-test/r/mysql.result
        mysql-test/t/mysql.test

It turned out the actual reason why the problematic test case is too slow was a non-optimal code in the CSV storage engine. 

ha_tina::encode_quote() is called for each SQL query before writing it to the general log (if logging to tables is on). What it does is copying the query text byte-by-byte, quoting characters that should be quoted and appending them to the output buffer. But, since the initial output buffer is set to 0, and String::append(char) can only grow the buffer by 1 byte, we end up calling realloc() for each byte in the input query. This is taking enormous time on a 2 MB query from the test case for bug #41486.

I'm going to fix this bug by disable the general log for the problematic query in the test case, and report the inefficiency in ha_tine::encode_quote() as a separate bug.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/70297

2838 Alexey Kopytov	2009-03-25
      Fix for bug #43801: mysql.test takes too long, fails due to 
                          expired timeout on debx86-b in PB
      
      Turned off general log when importing DB dump in the test 
      case for bug #41486 due to the bug in CSV engine code that 
      makes logging long SQL query too slow.
      modified:
        mysql-test/r/mysql-bug41486.result
        mysql-test/t/mysql-bug41486.test

The ha_tina::encode_quote() inefficiency has already been reported as bug #35165 "Logging to table is slow for large queries".

Pushed into 5.0.80 (revid:joro@sun.com-20090327142516-55gumdxj39z6eijj) (version source revid:alexey.kopytov@sun.com-20090324205059-x2kygp30gdmx2b2g) (merge vers: 5.0.80) (pib:6)

Pushed into 5.1.34 (revid:joro@sun.com-20090327143448-wuuuycetc562ty6o) (version source revid:alexey.kopytov@sun.com-20090325073201-1zqnlcyomkju917z) (merge vers: 5.1.34) (pib:6)

Test case changes. No changelog entry needed.

Setting report to NDI pending push into 6.0.x.

Pushed into 6.0.11-alpha (revid:alik@sun.com-20090413084402-snnrocwzktcl88ny) (version source revid:alexey.kopytov@sun.com-20090325073503-4pnysf19gi6z2cgb) (merge vers: 6.0.11-alpha) (pib:6)

Test case changes. No changelog entry needed.

Pushed into 5.1.34-ndb-6.2.18 (revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (version source revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (merge vers: 5.1.34-ndb-6.2.18) (pib:6)

Pushed into 5.1.34-ndb-6.3.25 (revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (version source revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (merge vers: 5.1.34-ndb-6.3.25) (pib:6)

Pushed into 5.1.34-ndb-7.0.6 (revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (version source revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (merge vers: 5.1.34-ndb-7.0.6) (pib:6)