Bug #29300 Falcon LOAD_DATA performance issue
Submitted: 22 Jun 2007 10:48 Modified: 29 Aug 2008 20:53
Reporter: Yoshinori Matsunobu Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:5.2.4-falcon-alpha OS:Any
Assigned to: Hakan Küçükyılmaz CPU Architecture:Any

[22 Jun 2007 10:48] Yoshinori Matsunobu
Description:
I tested a very simple loading(10 million records, 350MB text file) test, 
finding that Falcon takes much more time than InnoDB.

Result
InnoDB: 1 min 25.85 sec
Falcon: 2 min 28.92 sec

First two minutes average CPU user time was 90-100% (1 core only).
Cpu0  :  1.7% us,  1.0% sy,  0.0% ni, 97.0% id,  0.3% wa,  0.0% hi,  0.0% si
Cpu1  :  0.7% us,  1.0% sy,  0.0% ni, 97.0% id,  1.3% wa,  0.0% hi,  0.0% si
Cpu2  : 97.0% us,  3.0% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu3  :  0.0% us,  0.7% sy,  0.0% ni, 99.3% id,  0.0% wa,  0.0% hi,  0.0% si

The last 20-30 seconds CPU user time was 0-10%,
much time for I/O(wa), which I guess Falcon writes all records synchronously to the Serial Log file.
Cpu0  :  0.3% us,  0.0% sy,  0.0% ni, 99.7% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu1  :  0.0% us,  1.0% sy,  0.0% ni, 98.7% id,  0.0% wa,  0.0% hi,  0.3% si
Cpu2  : 12.3% us, 10.3% sy,  0.0% ni,  0.0% id, 77.5% wa,  0.0% hi,  0.0% si
Cpu3  :  3.0% us,  1.0% sy,  0.0% ni, 95.4% id,  0.7% wa,  0.0% hi,  0.0% si

Oprofile shows that Falcon uses much more CPU time than InnoDB, especially for DeferredIndex.
- Oprofile(Falcon)
samples  %        image name               symbol name
280148   10.5991  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld DeferredIndex::compare(IndexKey*, DINode*, bool)
270691   10.2413  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld DeferredIndex::compare(DINode*, DINode*)
104151    3.9405  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld Index::makeKey(Record*, IndexKey*)
99677     3.7712  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld READ_INFO::read_field()
99487     3.7640  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld DeferredIndexWalker::DeferredIndexWalker(DeferredIndex*, IndexKey*, int)
85704     3.2425  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld SyncObject::lock(Sync*, LockType)
84625     3.2017  /lib64/tls/libc-2.3.4.so memcpy
75397     2.8526  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld DeferredIndex::addNode(IndexKey*, int)
75093     2.8411  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld Cache::fetchPage(Dbb*, int, PageType, LockType)
72412     2.7396  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld SyncObject::unlock(Sync*, LockType)
51056     1.9317  /usr/lib/debug/lib/modules/2.6.9-42.0.10.ELsmp/vmlinux copy_user_generic_c

- Oprofile(InnoDB)
samples  %        image name               symbol name
106149    6.1960  /lib64/tls/libc-2.3.4.so memcpy
97978     5.7191  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld READ_INFO::read_field()
85442     4.9873  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld btr_search_guess_on_hash
80039     4.6720  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld rec_get_offsets_func
67413     3.9350  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld buf_calc_page_new_checksum
64571     3.7691  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld log_group_write_buf
42105     2.4577  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld btr_cur_optimistic_insert
39049     2.2793  /data/ymatsunobu/falcon-bench/mysql/libexec/mysqld mysql_load(THD*, sql_exchange*, st_table_list*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool)

How to repeat:
H/W:
AMD Opteron(tm) Processor 275, 1.8GHz * 4
8GB Memory

SQL:
CREATE TABLE t1 (c1 BIGINT PRIMARY KEY, c2 INT, c3 VARCHAR(100)) 
LOAD DATA LOCAL INFILE '/path/to/datafile' INTO TABLE t1 FIELDS TERMINATED BY ',';
(only 1 session. No concurrency test)

Data file:
1,1,ABCDEFGHIJabcdefghij
2,2,ABCDEFGHIJabcdefghij
...
10000000,10000000,ABCDEFGHIJabcdefghij
(10M rows)

-configure option
export CFLAGS="-O3 " CXXFLAGS="-O3 "
./configure \
--prefix=/data/ymatsunobu/falcon-bench/mysql \
--with-extra-charsets=complex \
--with-plugin-falcon \
--with-extra-charsets=all \
--with-partition \
--with-blackhole-storage-engine \
--with-archive-storage-engine \
--with-plugin-innobase

-my.cnf
[mysqld]
port            = 3306
socket          = /tmp/mysql.sock
basedir=/data/ymatsunobu/falcon-bench/mysql
datadir=/data/ymatsunobu/falcon-bench/mysql/data
skip-locking
key_buffer = 16M
table_cache = 512
sort_buffer_size = 512K
net_buffer_length = 8K
read_buffer_size = 256K
read_rnd_buffer_size = 512K
myisam_sort_buffer_size = 8M
default_storage_engine = Falcon
max_allowed_packet = 512M
falcon_log_mask = 8191
max_connections = 1000
falcon_page_cache_size = 1G
falcon_max_record_memory = 1G
falcon_record_chill_threshold=1000

innodb_data_file_path = ibdata1:100M:autoextend
innodb_buffer_pool_size = 2000M
innodb_additional_mem_pool_size = 20M
innodb_log_file_size = 650M
innodb_log_files_in_group = 2
innodb_log_buffer_size = 16M
innodb_flush_log_at_trx_commit = 1
innodb_flush_method = O_DIRECT
innodb_lock_wait_timeout = 50
innodb_support_xa=OFF
[25 Jun 2007 22:13] MySQL Verification Team
Thank you for the bug report.

Microsoft Windows [versão 6.0.6000]
Copyright (c) 2006 Microsoft Corporation. Todos os direitos reservados.

c:\dev>cd 6.0

c:\dev\6.0>bin\mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 6.0.1-alpha-nt Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> CREATE TABLE t1 (c1 BIGINT PRIMARY KEY, c2 INT, c3 VARCHAR(100)) engine=falcon;
Query OK, 0 rows affected (0.95 sec)

mysql> show create table t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `c1` bigint(20) NOT NULL,
  `c2` int(11) DEFAULT NULL,
  `c3` varchar(100) DEFAULT NULL,
  PRIMARY KEY (`c1`)
) ENGINE=Falcon DEFAULT CHARSET=latin1
1 row in set (0.06 sec)

mysql> load data infile 'c:/temp/datafile.sql' into table t1 fields terminated by ',' lines terminated by '\n';
Query OK, 10000000 rows affected (12 min 47.07 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

mysql>

c:\dev\6.0>bin\mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 6.0.1-alpha-nt Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> CREATE TABLE t1 (c1 BIGINT PRIMARY KEY, c2 INT, c3 VARCHAR(100)) engine=InnoDB;
Query OK, 0 rows affected (0.11 sec)

mysql> show create table t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `c1` bigint(20) NOT NULL,
  `c2` int(11) DEFAULT NULL,
  `c3` varchar(100) DEFAULT NULL,
  PRIMARY KEY (`c1`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> load data infile 'c:/temp/datafile.sql' into table t1 fields terminated by ',' lines terminated by '\n';
Query OK, 10000000 rows affected (6 min 15.04 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

small program to create the datafile:

#include <iostream>
#include <fstream>

using namespace std;

void main()
{
  ofstream out("c:\\temp\\datafile.sql");

   for (int n = 1; n <= 10000000; n++)
   {
     out << n << ',' << n+1 << ',' << "ABCDEFGHIJabcdefghij\n";
   }
}
[18 Oct 2007 22:30] Kevin Lewis
Miguel,  can you retest this both with mysql-6.0-falcon and with mysql-6.0-falcon -team?
[26 Oct 2007 9:20] Kevin Lewis
Please retest only with mysql-6.0-falcon.  I now has newer performance improvements.
[19 Nov 2007 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[11 Feb 2008 19:29] Philip Stoev
I am setting this bug to verifed because I have the following statistics using the latest mysql-6.0 tree:

Falcon:
mysql> load data local infile '/build/tests-6.0/mysql-test//suite/systems/data/tb1.txt'      into table tb1_eng1 (f1,f2,f3,f4 );
Query OK, 5000000 rows affected (8 min 9.23 sec)
Records: 5000000  Deleted: 0  Skipped: 0  Warnings: 0

Innob:
mysql> load data local infile '/build/tests-6.0/mysql-test//suite/systems/data/tb1.txt'      into table tb1_eng1 (f1,f2,f3,f4 );
Query OK, 5000000 rows affected (5 min 1.73 sec)
Records: 5000000  Deleted: 0  Skipped: 0  Warnings: 0

Table is:

create table tb1_eng1 (
i1 int NOT NULL auto_increment, primary key (i1),
f1 int,
f2 char (15),
f3 decimal (10,3),
f4 datetime
);
[27 Feb 2008 19:41] Kevin Lewis
Hakan or Yoshinori,  Can you verify if this LOAD DATA performance problem still exists.  I think that we identified a similar problem as a serialization in starting new transactions.  That is fixed in the current mysql-6.0-falcon and mysql-6.0-release 6.0.4 trees.  Please retest.
[29 Aug 2008 20:03] Kevin Lewis
Hakan,  Now that we can do an Online Add/Drop Index,  and this bug was opened over a year ago, can you or John do another test and re-verify this?
[29 Aug 2008 20:53] Hakan Küçükyılmaz
Can't repeat with latest Falcon code anymore:

[22:47] root@(none)>use test;
Database changed

[22:48] root@test>CREATE TABLE t1 (c1 BIGINT PRIMARY KEY, c2 INT, c3 VARCHAR(100)) ENGINE InnoDB;
Query OK, 0 rows affected (0.01 sec)

[22:48] root@test>load data local infile '/home/hakan/src/c/foo.txt' into table t1 fields terminated by ',';
Query OK, 10000000 rows affected (2 min 35.87 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0

[22:51] root@test>CREATE TABLE t2 (c1 BIGINT PRIMARY KEY, c2 INT, c3 VARCHAR(100)) Engine Falcon;
Query OK, 0 rows affected (0.09 sec)

[22:52] root@test>load data local infile '/home/hakan/src/c/foo.txt' into table t2 fields terminated by ',';
Query OK, 10000000 rows affected (2 min 6.03 sec)
Records: 10000000  Deleted: 0  Skipped: 0  Warnings: 0