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=1With 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
- [ 5 ] GNU gprof
- [ 6 ] Oprofile
- [ 7 ] SuSE oprofile presentation (PDF)