[MDEV-17667] MariaDB 10.3.8 looses last transaction Created: 2018-11-11  Updated: 2018-11-11  Resolved: 2018-11-11

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.8
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Oli Sennhauser Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: need_feedback
Environment:

Linux, Ubuntu 14.04

Attachments: File az_test.php    

 Description   

Our test script (az_test.php) does inserts into database. On error it reports last commited transaction:
Last id was: 17687

After (clean) restart of MariaDB 10.3.8 last commited transaction is not there any more:

SELECT COUNT(*) FROM aaa_fromdual.test UNION ALL SELECT COUNT(*) FROM zzz_fromdual.test;
 
+----------+
 
| COUNT(*) |
 
+----------+
 
|    17686 |
 
|    17686 |
 
+----------+

But General Log reports query as commited:

                    94 Query    START TRANSACTION
 
                    94 Query    INSERT INTO `aaa_fromdual`.`test` VALUES (NULL, "Test data on first table.", NULL)
 
                    94 Query    INSERT INTO `zzz_fromdual`.`test` VALUES (17687, "Test data on second table.", NULL)
 
                    94 Query    COMMIT
 
                    95 Query    shutdown

MySQL was properly restarted:

2018-11-11 18:32:33 0 [Note] /home/mysql/product/mariadb-10.3/bin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
 
2018-11-11 18:32:33 0 [Note] Event Scheduler: Purging the queue. 0 events                                                                          
2018-11-11 18:32:33 0 [Note] InnoDB: FTS optimize thread exiting.                                                                                  
2018-11-11 18:32:33 0 [Note] InnoDB: Starting shutdown...                                                                                          
2018-11-11 18:32:33 0 [Note] InnoDB: Dumping buffer pool(s) to /home/mysql/database/mariadb-103/data/ib_buffer_pool                                
2018-11-11 18:32:33 0 [Note] InnoDB: Instance 0, restricted to 2048 pages due to innodb_buf_pool_dump_pct=25                                       
2018-11-11 18:32:33 0 [Note] InnoDB: Buffer pool(s) dump completed at 181111 18:32:33                                                                              
2018-11-11 18:32:34 0 [Note] InnoDB: Shutdown completed; log sequence number 859835539; transaction id 75652                                                       
2018-11-11 18:32:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"                                                                                                   
2018-11-11 18:32:34 0 [Note] /home/mysql/product/mariadb-10.3/bin/mysqld: Shutdown complete                                                                                             
                                                                                                                                                                                        
2018-11-11 18:33:10 0 [Note] InnoDB: Using Linux native AIO
 
2018-11-11 18:33:10 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2018-11-11 18:33:10 0 [Note] InnoDB: Uses event mutexes
 
 
 
2018-11-11 18:33:10 0 [Note] InnoDB: Number of pools: 1This problem does not happen with your competitor.
 
 
 
2018-11-11 18:33:10 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2018-11-11 18:33:10 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2018-11-11 18:33:10 0 [Note] InnoDB: Completed initialization of buffer pool
 
2018-11-11 18:33:10 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2018-11-11 18:33:10 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2018-11-11 18:33:10 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2018-11-11 18:33:10 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2018-11-11 18:33:10 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2018-11-11 18:33:10 0 [Note] InnoDB: 10.3.8 started; log sequence number 859835539; transaction id 75654
 
2018-11-11 18:33:10 0 [Note] InnoDB: Loading buffer pool(s) from /home/mysql/database/mariadb-103/data/ib_buffer_pool
 
2018-11-11 18:33:10 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2018-11-11 18:33:10 0 [Note] InnoDB: Buffer pool(s) load completed at 181111 18:33:10
 
2018-11-11 18:33:10 0 [Note] Server socket created on IP: '::'.
 
2018-11-11 18:33:10 0 [Note] Reading of all Master_info entries succeded
 
2018-11-11 18:33:10 0 [Note] Added new Master_info '' to hash table
 
2018-11-11 18:33:10 0 [Note] /home/mysql/product/mariadb-10.3/bin/mysqld: ready for connections.
 
Version: '10.3.8-MariaDB-log'  socket: '/var/run/mysqld/mysql-3320.sock'  port: 3320  MariaDB Server

Config was nothing sophisticated:

[mysqld]
 
 
 
port                           = 3320
 
socket                         = /var/run/mysqld/mysql-3320.sock                              # Use mysqld.sock on Ubuntu, conflicts with AppArmor otherwise
 
basedir                        = /home/mysql/product/mariadb-10.3
 
datadir                        = /home/mysql/database/mariadb-103/data
 
log_error                      = /home/mysql/database/mariadb-103/log/error.log
 
log_bin                        = /home/mysql/database/mariadb-103/binlog/binlog
 
performance_schema             = on
 
performance_schema_consumer_events_statements_history_long = ON
 
general_log                    = 1
 
general_log_file               = /home/mysql/database/mariadb-103/log/general.log

This problem does not happen with your competitor. And it is reproducible every time at will.

 Comments   
Comment by Elena Stepanova [ 2018-11-11 ]

It seems to be working okay for me, tried a few times:

                    11 Query    START TRANSACTION
 
                    11 Query    INSERT INTO `aaa_fromdual`.`test` VALUES (NULL, "Test data on first table.", NULL)
 
                    11 Query    INSERT INTO `zzz_fromdual`.`test` VALUES (506, "Test data on second table.", NULL)
 
                    11 Query    COMMIT
 
                    12 Query    shutdown


MariaDB [test]>   SELECT COUNT(*) FROM aaa_fromdual.test UNION ALL SELECT COUNT(*) FROM zzz_fromdual.test;
 
+----------+
 
| COUNT(*) |
 
+----------+
 
|      506 |
 
|      506 |
 
+----------+
 
2 rows in set (0.00 sec)
 
 
 
MariaDB [test]> select @@version;
 
+--------------------+
 
| @@version          |
 
+--------------------+
 
| 10.3.8-MariaDB-log |
 
+--------------------+
 
1 row in set (0.01 sec)

Could you please provide SHOW CREATE for the table, maybe there is something in there?

Comment by Oli Sennhauser [ 2018-11-11 ]

Both the same:

CREATE TABLE `test` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`data` varchar(128) DEFAULT NULL,
`ts` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(),
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=17688 DEFAULT CHARSET=latin1

I try to get a 10.3.10 to reproduce... But having bad Internet connection ...

I do not know if this helps to fence the problem: I am using generic binary tar ball...

Comment by Oli Sennhauser [ 2018-11-11 ]

And Result is in Binary Logs as well:

  1. at 3233842
    #181111 18:32:33 server id 1 end_log_pos 3233884 CRC32 0x9dd5d51b GTID 0-1-25923 trans
    /Unable to render embedded object: File (100001 SET @@session.gtid_seq_no=25923*//*) not found./;
    BEGIN
    /!/;
  2. at 3233884
    #181111 18:32:33 server id 1 end_log_pos 3233916 CRC32 0x9a00d9fc Intvar
    SET INSERT_ID=17687/!/;
  3. at 3233916
    #181111 18:32:33 server id 1 end_log_pos 3234061 CRC32 0x1e73de18 Query thread_id=94 exec_time=0 error_code=0
    SET TIMESTAMP=1541957553/!/;
    INSERT INTO `aaa_fromdual`.`test` VALUES (NULL, "Test data on first table.", NULL)
    /!/;
  4. at 3234061
    #181111 18:32:33 server id 1 end_log_pos 3234208 CRC32 0x5d251f86 Query thread_id=94 exec_time=0 error_code=0
    SET TIMESTAMP=1541957553/!/;
    INSERT INTO `zzz_fromdual`.`test` VALUES (17687, "Test data on second table.", NULL)
    /!/;
  5. at 3234208
    #181111 18:32:33 server id 1 end_log_pos 3234239 CRC32 0x2bce270a Xid = 32864
    COMMIT/!/;
  6. at 3234239
    #181111 18:32:33 server id 1 end_log_pos 3234262 CRC32 0xe9d0f23e Stop
    DELIMITER ;
  7. End of log file
    ROLLBACK /* added by mysqlbinlog */;
    /!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE/;
    /!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0/;
Comment by Oli Sennhauser [ 2018-11-11 ]

Upgraded to 10.3.10 and same problem...
Trying to completely remove instance now.

Comment by Oli Sennhauser [ 2018-11-11 ]

After new creation of instance problem has gone! I tried it 5 times and it did not happen any more. So the old instance seems to have some odd inheritance from an earlier experiment...

Comment by Elena Stepanova [ 2018-11-11 ]

That's very disturbing. We'll probably have to close it for now, but please keep an eye on it, and if it ever re-appears, comment so that we could re-open and investigate the issue.

Generated at Thu Feb 08 08:38:11 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.