You are here

Profiling MySQL with oprofile

Why is is data load with LOAD DATA INFILE so much faster?

Probably the answer to this question is already known. But we want to prove it and by the way learn to deal with oprofile.

For the test MySQL 5.0.28 was used and 100k rows were loaded into a table sales which looks as follows:

CREATE TABLE sales (
    sales_id       INT UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY
  , product_name   VARCHAR(128) NOT NULL
  , product_price  DECIMAL(8,2) NOT NULL
  , product_amount SMALLINT     NOT NULL
) ENGINE = MyISAM;

The following load times were messured:

Test MyISAM InnoDB Remarks
LOAD DATA INFILE 0.85 s 2.51 s
Multi row INSERT 2.69 s 4.48 s
Single row INSERT 15.0 s 881 s [ 1 ]
Single row INSERT
w/o LOCK TABLE
15.1 s 18.1 s [ 2 ]

But now we want to know what happens into mysqld during this load. For measuring this see also:

opcontrol --init
opcontrol --setup --separate=lib,kernel,thread --no-vmlinux
opcontrol --start-daemon
ps axuwww| grep opro
opcontrol --start
do the action to trace here...
opcontrol --dump
opreport --demangle=smart --symbols --long-filenames --merge tgid \
$(which mysqld) | head -n 20
opcontrol --stop
opcontrol --deinit
opcontrol --reset

For the fast running test it was run several times (5-10 times).

LOAD DATA INFILE

MyISAM

samples  %        image name               symbol name
1125     13.3674  .../bin/mysqld           .my_strtoll10_end
755       8.9710  .../bin/mysqld           ha_key_cmp
464       5.5133  .../bin/mysqld           READ_INFO::read_field()
418       4.9667  .../bin/mysqld           _mi_bin_search
402       4.7766  /no-vmlinux              (no symbols)
287       3.4102  /lib/tls/libc.so.6       __GI_memcpy
261       3.1012  .../bin/mysqld           read_sep_field(THD*, ...)
227       2.6972  .../bin/mysqld           w_search
199       2.3645  /lib/tls/libpthread.so.0 __pthread_mutex_unlock_usercnt
195       2.3170  .../bin/mysqld           decimal2bin
185       2.1982  .../bin/mysqld           mi_write
181       2.1507  /lib/tls/libpthread.so.0 __pthread_mutex_lock_internal
181       2.1507  .../bin/mysqld           _mi_rec_pack
181       2.1507  .../bin/mysqld           key_cache_read
175       2.0794  .../bin/mysqld           internal_str2dec
172       2.0437  .../bin/mysqld           find_key_block

InnoDB

samples  %        image name               symbol name
1090      6.1981  /no-vmlinux              (no symbols)
744       4.2306  /lib/tls/libpthread.so.0 __pthread_mutex_trylock
658       3.7416  /lib/tls/libc.so.6       __GI_memcpy
621       3.5312  .../bin/mysqld           rec_init_offsets
608       3.4573  /lib/tls/libpthread.so.0 __pthread_mutex_unlock_usercnt
493       2.8034  .../bin/mysqld           READ_INFO::read_field()
487       2.7692  .../bin/mysqld           decimal2bin
441       2.5077  .../bin/mysqld           read_sep_field(THD*, ...)
438       2.4906  .../bin/mysqld           ha_innobase::write_row(char*)
402       2.2859  .../bin/mysqld           log_group_write_buf
387       2.2006  .../bin/mysqld           page_cur_insert_rec_low
381       2.1665  .../bin/mysqld           row_insert_for_mysql
364       2.0698  .../bin/mysqld           mem_area_free

Multi row INSERT

MyISAM

samples  %        image name               symbol name
7277     22.3887  .../bin/mysqld           MYSQLparse(void*)
2591      7.9716  /no-vmlinux              (no symbols)
2269      6.9809  .../bin/mysqld           .my_strtoll10_end
1507      4.6365  .../bin/mysqld           ha_key_cmp
1250      3.8458  .../bin/mysqld           setup_fields(THD*, ...)
963       2.9628  .../bin/mysqld           THD::cleanup_after_query()
926       2.8490  .../bin/mysqld           MYSQLlex(void*, void*)
879       2.7044  .../bin/mysqld           fill_record(THD*, ...)
864       2.6582  .../bin/mysqld           _mi_bin_search
678       2.0860  /lib/tls/libc.so.6       __GI_memcpy

InnoDB

samples  %        image name               symbol name
7147     22.0505  .../bin/mysqld           MYSQLparse(void*)
2846      8.7807  /no-vmlinux              (no symbols)
1264      3.8998  .../bin/mysqld           setup_fields(THD*, ...)
957       2.9526  .../bin/mysqld           MYSQLlex(void*, void*)
918       2.8323  .../bin/mysqld           THD::cleanup_after_query()
812       2.5052  .../bin/mysqld           fill_record(THD*, ...)
740       2.2831  /lib/tls/libpthread.so.0 __pthread_mutex_trylock
720       2.2214  /lib/tls/libc.so.6       __GI_memcpy

Single row INSERT

MyISAM

samples  %        image name               symbol name
19612    38.0793  /no-vmlinux              (no symbols)
5707     11.0809  .../bin/mysqld           MYSQLparse(void*)
1116      2.1669  .../bin/mysqld           MYSQLlex(void*, void*)
1057      2.0523  .../bin/mysqld           .my_strtoll10_end
740       1.4368  /lib/tls/libc.so.6       _IO_vfprintf_internal
737       1.4310  .../bin/mysqld           mysql_insert(THD*, ...)
570       1.1067  .../bin/mysqld           dispatch_command(...)

InnoDB

samples  %        image name               symbol name
12005    34.1809  /no-vmlinux              (no symbols)
2458      6.9985  .../bin/mysqld           MYSQLparse(void*)
456       1.2983  .../bin/mysqld           mysql_insert(THD*, ...)
454       1.2926  .../bin/mysqld           log_group_write_buf
430       1.2243  .../bin/mysqld           MYSQLlex(void*, void*)
399       1.1360  /lib/tls/libpthread.so.0 __pthread_mutex_trylock
370       1.0535  /lib/tls/libc.so.6       __GI_memcpy
353       1.0051  /lib/tls/libpthread.so.0 __pthread_mutex_unlock_usercnt

Single row INSERT w/o LOCK TABLE

MyISAM

samples  %        image name               symbol name
26021    39.7662  /no-vmlinux              (no symbols)
6327      9.6691  .../bin/mysqld           MYSQLparse(void*)
1210      1.8492  .../bin/mysqld           .my_strtoll10_end
1210      1.8492  .../bin/mysqld           MYSQLlex(void*, void*)
894       1.3662  .../bin/mysqld           mysql_insert(THD*, ...)
785       1.1997  /lib/tls/libpthread.so.0 __pthread_mutex_lock_internal
778       1.1890  /lib/tls/libc.so.6       _IO_vfprintf_internal

InnoDB

samples  %        image name               symbol name
3375     25.2866  /no-vmlinux              (no symbols)
1324      9.9198  .../bin/mysqld           MYSQLparse(void*)
243       1.8206  .../bin/mysqld           MYSQLlex(void*, void*)
164       1.2287  /lib/tls/libpthread.so.0 __pthread_mutex_unlock_usercnt
164       1.2287  .../bin/mysqld           mysql_insert(THD*, ...)
155       1.1613  /lib/tls/libc.so.6       _IO_vfprintf_internal
153       1.1463  /lib/tls/libc.so.6       __GI_memcpy
149       1.1164  /lib/tls/libpthread.so.0 __pthread_mutex_trylock
148       1.1089  .../bin/mysqld           dispatch_command(...)
145       1.0864  /lib/tls/libpthread.so.0 __pthread_mutex_lock_internal

Findings

Parsing (MYSQLparse) and lexical checking (MYSQLlex) use to most time in test 2-4. Where in test 3 and 4 lexical checking uses more time than in 2 (what we already expected at in the beginning).

InnoDB is already fighting with threading library and transactions.

Unfortunately IO waiting is not seen in this output here. I have to find out how and if this can be found...

Tests

TRUNCATE TABLE sales;
LOAD DATA
INFILE '/tmp/sales_outfile_100k.dmp'
INTO TABLE sales;

time mysql -u root test << EOF;
TRUNCATE TABLE sales;
SOURCE /tmp/sales_multirowinsert_100k.sql
EOF

time mysql -u root test << EOF;
TRUNCATE TABLE sales;
SOURCE /tmp/sales_extended_100k.sql
EOF

time mysql -u root test << EOF;
TRUNCATE TABLE sales;
SOURCE /tmp/sales_extended_nolock_100k.sql
EOF

Footnotes

[ 1 ] CPU is idling, fully disk bound: innodb_flush_log_at_trx_commit=1

With IOstat we can see that the transaction logging is our problem: The System is fully idling:

# iostat -x 1

avg-cpu:  %user   %nice    %sys %iowait   %idle
           3.00    0.00    2.00    0.00   95.00

Device: rrqm/s wrqm/s  r/s   w/s  rsec/s wsec/s rkB/s  wkB/s avgrq-sz avgqu-sz await svctm %util
hda       0.00   3.00 0.00 120.00   0.00 984.00  0.00 492.00     8.20     0.00  0.03  0.03  0.30

From this output we can see that we do 120 w/s (which relates to 7200 rpm) and we are writing 984 sectors per seconds. This is related to 492 kbyte per second. Thus one block is 512 bytes and one write is 4 kbyte.

Expected duration of the test is: 100'000 records / (7200 rpm / 60 s) = 833 seconds.

[ 2 ] innodb_flush_log_at_trx_commit=0 to safe time.

Literature