Bug #24169 Dramatic speed loss when going from 5.1.11 to 5.1.12 (or to 5.0.26)
Submitted: 10 Nov 2006 7:41 Modified: 28 Feb 2007 7:26
Reporter: Martin Boer Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.1.12, 5.1.14 OS:Linux (Linux (Debian/Sarge))
Assigned to: Valeriy Kravchuk CPU Architecture:Any
Tags: 5.1.11, regression

[10 Nov 2006 7:41] Martin Boer
Description:
Sorry to make this one critical, but for me it is. 

Migrating from 5.1.11 to 5.1.12 gave us a dramatic performance decrease. And with dramatic I mean that our testquery (which is typical for a part of the application now needs 7 seconds instead of 0.15)

The reason we use 5.1.x instead of 5.0.26 is that the latter also gave us the same terrible performance. Our current production system is running 4.1.7 which is doing fine most of the time but sometimes can't cope with the stress resulting in a very slow userinterface. We hoped going to 5 would give us some more performance and as we are migrating the platform anyway we combined the MySQL upgrade with it but the new versions, except 5.1.11, are much worse.
5.1.11 is a bit faster than the 4.1.7 version.

Below (in the How to repeat field) I've included some output using the testquery.

How to repeat:
Start query .... timetaken@1163146850: 7.10825
Start query .... timetaken@1163146858: 7.148429
Start query .... timetaken@1163146866: 9.483118
Start query .... timetaken@1163146877: 7.253773
Start query .... timetaken@1163146885: 7.205977
Start query .... timetaken@1163146893: 7.204991
Start query .... timetaken@1163146902: 7.268858
Start query .... timetaken@1163146910: 9.120673
Start query .... timetaken@1163146920: 7.488501
Start query .... timetaken@1163146928: 7.653398
Start query .... timetaken@1163146937: 7.196534
Start query .... timetaken@1163146945: 7.112914

(root@hdbeat05)-(09:22 AM Fri Nov 10)-(mysql)
# /etc/init.d/mysql.server stop
Shutting down MySQL. SUCCESS!
(root@hdbeat05)-(09:22 AM Fri Nov 10)-(mysql)
# ls -l
total 0
drwxr-xr-x  10 root mysql 272 Nov  9 16:12 5.1.11
drwxr-xr-x  10 root mysql 272 Nov  9 17:00 5.1.12
lrwxrwxrwx   1 root root    6 Nov 10 09:09 active -> 5.1.12
(root@hdbeat05)-(09:22 AM Fri Nov 10)-(mysql)
# rm active
(root@hdbeat05)-(09:23 AM Fri Nov 10)-(mysql)
# ln -s 5.1.11 active
(root@hdbeat05)-(09:23 AM Fri Nov 10)-(mysql)
# /etc/init.d/mysql.server start
Starting MySQL SUCCESS!
(root@hdbeat05)-(09:23 AM Fri Nov 10)-(mysql)
# /afs1/beat/bin/checkdb.pl
Start query .... timetaken@1163147000: 0.148816
Start query .... timetaken@1163147002: 0.000434
Start query .... timetaken@1163147003: 0.000426
Start query .... timetaken@1163147004: 0.000435
Start query .... timetaken@1163147005: 0.008259
Start query .... timetaken@1163147006: 0.000449
Start query .... timetaken@1163147007: 0.000419
Start query .... timetaken@1163147008: 0.000398

Our current production system (using 4.1.7) goes a bit like this:
Start query .... timetaken@1163144075: 0.190287
Start query .... timetaken@1163144077: 0.196754
Start query .... timetaken@1163144078: 0.187411
Start query .... timetaken@1163144079: 0.18891
Start query .... timetaken@1163144080: 0.186744
Start query .... timetaken@1163144081: 0.216677
So 5.1.11 IS faster.
[10 Nov 2006 8:29] Valeriy Kravchuk
Thank you for a problem report. Please, upload your database and test query to:

ftp://ftp.mysql.com/pub/mysql/upload/

Use bug number (24169) in file names. Add comment to this report when finished.
[10 Nov 2006 9:40] Martin Boer
Hi, 
thanks for your fast response.

At this moment I'm uploading the files, but the database tgz file takes quite long. As I use the unix ftp client I can't see if it still is doing something. Can you tell if the file is still increasing in size ? Using another connection told me I dont have read-permission in the upload directory (which makes sense).
It is probably my upload speed which is restricted. 

When this upload is finished I still need to upload our my.cnf
[10 Nov 2006 10:09] Martin Boer
Okay... if everything is correct you now have 
A perlscipt, a perl module, 2 databases and a my.cnf.
I used the following for the compilation of MySQL.

#!/bin/bash
cd mysql-5.1.12-beta
CFLAGS="-O3"
CXX=gcc
CXXFLAGS="-O3 -felide-constructors -fno-exceptions -fno-rtti"
export CFLAGS
export CXX
export CXXFLAGS
./configure --enable-assembler  --with-mysqld-ldflags=-all-static --prefix=/afs1/mysql/5.1.12 --localstatedir=/afs2/mysql/active/data --with-unix-socket-path=/afs2/mysql/active/data/mysql.sock --with-mysqld-user=mysql
[10 Nov 2006 10:47] Valeriy Kravchuk
Please, confirm that file sizes are OK:

mysqldev@production:~> ls -l /supportftp/pub/mysql/upload/*24169*
--w-rw----  1 ftpuploads myftp    2927 Nov 10 09:47 /supportftp/pub/mysql/upload
/beat-24169.pm
--w-rw----  1 ftpuploads myftp    1259 Nov 10 09:47 /supportftp/pub/mysql/upload
/checkdb-24169.pl
--w-rw----  1 ftpuploads myftp 7322643 Nov 10 10:53 /supportftp/pub/mysql/upload
/db-nagios-24169.tgz
--w-rw----  1 ftpuploads myftp   50533 Nov 10 10:53 /supportftp/pub/mysql/upload
/db-userobjects-24169.tgz
--w-rw----  1 ftpuploads myftp     762 Nov 10 11:03 /supportftp/pub/mysql/upload
/my-24169.cnf
[22 Dec 2006 12:06] Valeriy Kravchuk
Please, try to repeat with a newer version, 5.1.14, and inform about the results.
[28 Dec 2006 9:39] Martin Boer
I just compiled/installed 5.1.14-beta using the same variables as before but just like 5.1.12 the test query takes around 7 seconds: 
# ./checkdb.pl
Start query .... timetaken@1167298496: 7.47562
Start query .... timetaken@1167298505: 7.633205
Start query .... timetaken@1167298514: 7.499059

I hope this helps (but I got this feeling it doesn't).
[12 Feb 2007 14:01] Valeriy Kravchuk
Sorry for a delay with htis report. I had dowloaded and checked your files. First of all, you sent me tables from 4.1.x (note Version 9):

mysql> show table status like 'config_services'\G
*************************** 1. row ***************************
           Name: config_services
         Engine: MyISAM
        Version: 9
     Row_format: Dynamic
           Rows: 14864
 Avg_row_length: 280
    Data_length: 4193524
Max_data_length: 4294967295
   Index_length: 215040
      Data_free: 30276
 Auto_increment: 19434
    Create_time: 2006-10-19 11:23:57
    Update_time: 2006-11-10 10:36:19
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.01 sec)

Have you dumped and restored them in 5.1.x before using? If not, please, do. Please, send also the results of EXPLAIN for the query you had used in your *.pl code from both 5.1.11 ("fast") and 5.1.12 (or 5.1.14), "slow".
[20 Feb 2007 8:24] Valeriy Kravchuk
Still need EXPLAIN results from "fast" and "slow" versions. We may have new optimizer bug/changed behaviour here because of some other bug fix. Please, after getting these EXPLAIN results, run ANALIZE on table(s) involved (on "slow" version) and check if runtimes and EXPLAIN results will change.
[28 Feb 2007 7:26] Valeriy Kravchuk
Problem fixed by reporter.