Profiling MySQL with oprofile
Sat, 2010-03-13 14:26 —
oli
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 <br>
$(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
[ 5
] GNU gprof
[ 6
] Oprofile
[ 7
] SuSE oprofile presentation (PDF)
