I bumped up innodb_log_file_size to 150M and my transaction took just as long as before. Those are the new stats below.
I'm surprised I didn't see innodb_buffer_pool_size and innodb_log_file_size as performance config points before, it seems they're all over the web.
I definitely need to get this transaction time down. But I added up all the millisecond times logged for every operation and it totalled only 16 seconds. I think it could be down to ORM layer unless I made a mistake.
One other curious occurence is that this transaction is the second in user's process. The first process inserts exactly the same number of records into TRADE, say 20K, but only takes 5 mins. What could cause the slow-down on the second transaction? The relationship is 1 to 1 so the there is a select for every trade and then it's child is inserted. But that should treble the time, should it?
Do you see anything out of order below?
mysql> SHOW VARIABLES LIKE '%log%';
+---------------------------------+------------+
| Variable_name | Value |
+---------------------------------+------------+
| back_log | 50 |
| binlog_cache_size | 32768 |
| expire_logs_days | 10 |
| innodb_flush_log_at_trx_commit | 1 |
| innodb_locks_unsafe_for_binlog | OFF |
| innodb_log_arch_dir | |
| innodb_log_archive | OFF |
| innodb_log_buffer_size | 1048576 |
| innodb_log_file_size | 157286400 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
| innodb_mirrored_log_groups | 1 |
| log | OFF |
| log_bin | OFF |
| log_bin_trust_function_creators | OFF |
| log_error | |
| log_queries_not_using_indexes | ON |
| log_slave_updates | OFF |
| log_slow_queries | ON |
| log_warnings | 1 |
| max_binlog_cache_size | 4294967295 |
| max_binlog_size | 104857600 |
| max_relay_log_size | 0 |
| relay_log_purge | ON |
| relay_log_space_limit | 0 |
| sync_binlog | 0 |
+---------------------------------+------------+
26 rows in set (0.00 sec)
mysql> SHOW GLOBAL STATUS LIKE '%log%';
+------------------------------+---------+
| Variable_name | Value |
+------------------------------+---------+
| Binlog_cache_disk_use | 0 |
| Binlog_cache_use | 0 |
| Com_show_binlog_events | 0 |
| Com_show_binlogs | 0 |
| Com_show_logs | 0 |
| Innodb_log_waits | 0 |
| Innodb_log_write_requests | 12437 |
| Innodb_log_writes | 453 |
| Innodb_os_log_fsyncs | 515 |
| Innodb_os_log_pending_fsyncs | 0 |
| Innodb_os_log_pending_writes | 0 |
| Innodb_os_log_written | 5738496 |
| Tc_log_max_pages_used | 0 |
| Tc_log_page_size | 0 |
| Tc_log_page_waits | 0 |
+------------------------------+---------+
15 rows in set (0.00 sec)
mysql> SHOW GLOBAL STATUS LIKE '%time';
+----------------------+-------+
| Variable_name | Value |
+----------------------+-------+
| Innodb_row_lock_time | 0 |
| Uptime | 1160 |
+----------------------+-------+
2 rows in set (0.00 sec)
Edited 1 time(s). Last edit at 06/18/2010 05:57AM by Adam Hardy.