MySQL Commited data not seen to select query

javaMySQLmysql-5.6transaction

Context: The framework used is Spring and all queries are run with JdbcTemplate. Mysql Server version is 5.6.19. The table is an InnoDB table and defaults like auto commit and isolation level repeatable-read is set.

Problem: An Insert happens inside a transaction and a select which reads the same data inserted does not see the data. The select runs after the insert and after the insert transaction has commited.

I've enabled bin log as well as general log in mysql. Relevant logs below

bin-log:

SET TIMESTAMP=1438265764/*!*/;
BEGIN
/*!*/;
# at 249935389
#150730 14:16:04 server id 1  end_log_pos 249935606 CRC32 0xa6aca292    Query   thread_id=40    exec_time=0     error_code=0
SET TIMESTAMP=1438265764/*!*/;
insert into user_geo_loc_latest(user_id, lat, lng) values(x,y,z) on duplicate key update lat=y, lng=z
/*!*/;
# at 249935606
#150730 14:16:06 server id 1  end_log_pos 249936255 CRC32 0x2a52c734    Query   thread_id=40    exec_time=0     error_code=0
SET TIMESTAMP=1438265766/*!*/;
INSERT INTO table(txnid) VALUES ('885851438265675046')
/*!*/;
# at 249936255
#150730 14:16:06 server id 1  end_log_pos 249936514 CRC32 0x6cd85eb5    Query   thread_id=40    exec_time=0     error_code=0
SET TIMESTAMP=1438265766/*!*/;
INSERT INTO table2(x) VALUES (y)
/*!*/;
# at 249936514
#150730 14:16:06 server id 1  end_log_pos 249936545 CRC32 0xceb9ec56    Xid = 9406873
COMMIT/*!*/;

Query Log

150730 14:16:04    40 Query ...
....
40 Query     select count(*) from table where txnid = '885851438265675046'
                   40 Query     select @@session.tx_read_only
                   40 Query     INSERT INTO table(txnid) VALUES ('885851438265675046')
                   40 Query     select @@session.tx_read_only
                   40 Query     INSERT INTO table2(x) values(y)
                   40 Query     commit
....
150730 14:16:07    36 Query     select pp.*, b.create_date from table pp left join bill b on pp.bill_id = b.bill_id where pp.txnid = '885851438265675046'

Curiously, First insert (249935389) should not be part of the transaction at all. It is a separate API call and completely unrelated. It could be spring mixing it with the transaction or I am reading the log wrong? AFAIK since it's on the same thread it implies the insert is in the transaction.

The next two inserts are part of the transaction and it looks like it commits. (249936514). Now the select query (last one in general log) runs after the commit and it does not see the data. It returns 0 rows. How can this happen considering the data is committed? Or is the commit not on the thread 40? Since it does not have the thread id.

To summarize I have two questions.

  1. Does the BEGIN in the binlog being before the INSERT INTO user_geo_loc (which is not part of the transaction), is this a bug with spring/Jdbc or MySql simply does this as it knows this transaction has already committed (as transactions are written to binlog when they've succeeded) and therefore would never be rolled back.

  2. Given the commit happens before the select (commit is at 14:16:06 and select is at 14:16:07) how is it that the select does not return the row inserted by the transaction?

This is extremely perplexing. Any help would be appreciated

Note: The queries in both the bin and query log have been edited to remove sensitive information. But the essence of the queries remain the same

Edit: Updated with general log and query log with a detailed example.

Best Answer

I try to make an hypothesis about the second question:

Given the commit happens before the select (commit is at 14:16:06 and select is at 14:16:07) how is it that the select does not return the row inserted by the transaction?

Transactions are managed by Spring. So it would be possible that before running the select spring has raised a start transaction or it has already used the connection for running an another query.

I start a first session where I simulate an insert into a table t:

session1> create table t (i int auto_increment primary key);
Query OK, 0 rows affected (0,32 sec)

session1> insert into t values();
Query OK, 1 row affected (0,00 sec)

session1> select * from t;
+---+
| i |
+---+
| 1 |
+---+
1 row in set (0,00 sec)

session1> start transaction;
Query OK, 0 rows affected (0,00 sec)

session1> insert into t values();
Query OK, 1 row affected (0,00 sec)

I create a new session, session2, where autocommit is set to 0. Into this new session, a transaction is implicitly started when running a select.

session2> set autocommit = 0;
Query OK, 0 rows affected (0,00 sec)

session2> select * from t;  -- this starts a transaction
+---+
| i |
+---+
| 1 |
+---+
1 rows in set (0,00 sec)

Move to session1 to commit the insert.

session1> commit;

Now move again to session2:

session2> select * from t;
+---+
| i |
+---+
| 1 |
+---+
1 row in set (0,00 sec)

Session2 cannot see the row just inserted. If a commit is raised in session2 we can see new row inserted in session1

session2> commit
1 row in set (0,00 sec)

session2> select * from t;
+---+
| i |
+---+
| 1 |
| 2 |
+---+
2 rows in set (0,00 sec)

The general log looks like :

150804 14:04:10     2 Query select * from t

150804 14:04:30     1 Query start transaction
150804 14:04:39     1 Query insert into t values ()
150804 14:04:44     1 Query commit
150804 14:04:51     2 Query select * from t

150804 14:05:07     2 Query commit
150804 14:05:10     2 Query select * from t

The first row is related to session 2. It is when session 2 opens the transaction.

I don't know if this is what happen in your case. You could check in your general log if the connection_id 36 was used for other queries. Let we know.

Related Question