The explain in my first posts is for the query. Or did you realise that already?
Regarding the memory, I have had a Java app running continously over the last 10 days or so and it is probably hogging the memory, but I just set innodb_buffer_pool_size = 1G because I have 2G and this other stuff running, but unfortunately it made no difference to the time of the transaction.
I just did some more digging around now that I have time to look at the issue again: I am slightly worried that what I'm seeing is pretty much decent performance.
This one transaction now takes 15 mins and from a count in the logs, it does:
6771 selects
6627 inserts
6894 updates
A few of those selects and updates are the primary key table, but not many.
The updates surprised me - I think there is a probably with the ORM layer here that I can investigate with them. But still assuming they take up 1/3 of the time, 10 mins for the remainder is still a fairly substantial amount of time, isn't it?
More rooting around showed that the longest operation was this, which took 257 ms:
FINEST: <t 14375743, conn 4308745> executing prepstmnt 27138522
INSERT INTO DOLLAR_RETURN (ID, MARKET_SYSTEM_ID, TRADE_ID, PROFIT,
OWNER_ID, VERSION, CREATED, MODIFIED)
VALUES (?, ?, ?, ?, ?, ?, ?, ?)
[params=(long) 4366899, (long) 11450, (long) 4388863, (BigDecimal) -0.000740000000, (long) 1, (int) 1, (Timestamp) 2010-06-15 11:45:14.013, (Timestamp) 2010-06-15 11:47:19.031]
15-Jun-2010 11:47:30 org.apache.openjpa.lib.log.CommonsLogFactory$LogAdapter trace
FINEST: <t 14375743, conn 4308745> [279 ms] spent
However it does thousands of these at under 1ms each but there are some taking around 40ms. I guess this one must be allocating more disk space or something.
Then I have this one:
INSERT INTO MARKET_SYSTEM (ID, TEST_RUN_ID, AVG_TRUE_RANGE, UNIT_VALUE,
COMMISSION, AVG_SPREAD, AVG_SLIPPAGE, MAX_SLIPPAGE, CURRENCY,
OWNER_ID, VERSION, CREATED, MODIFIED)
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
[params=(long) 11450, (long) 11650, (BigDecimal) 0.001000, (BigDecimal) 1.00, (BigDecimal) 0.000040, (BigDecimal) 0.000100, (BigDecimal) 0.000100, (BigDecimal) 0.001000, (String) USD, (long) 1, (int) 1, (Timestamp) 2010-06-15 11:44:39.333, (Timestamp) 2010-06-15 11:47:18.712]
15-Jun-2010 11:47:22 org.apache.openjpa.lib.log.CommonsLogFactory$LogAdapter trace
FINEST: <t 14375743, conn 4308745> [143 ms] spent
which only executes once. So I guess it would be best to concentrate on the insert into DOLLAR_RETURN.
Here are some of those stats:
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 | 5242880 |
| 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 | 12184 |
| Innodb_log_writes | 446 |
| Innodb_os_log_fsyncs | 503 |
| Innodb_os_log_pending_fsyncs | 0 |
| Innodb_os_log_pending_writes | 0 |
| Innodb_os_log_written | 5669888 |
| 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 | 13715 |
+----------------------+-------+
2 rows in set (0.00 sec)
This was after I restarted with the new innodb_buffer_pool_size and ran through the app's process once.