Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Cannot Reproduce
-
10.3.8
-
Linux, Ubuntu 14.04
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.
Attachments
Activity
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...
And Result is in Binary Logs as well:
- 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
/!/; - at 3233884
#181111 18:32:33 server id 1 end_log_pos 3233916 CRC32 0x9a00d9fc Intvar
SET INSERT_ID=17687/!/; - 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)
/!/; - 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)
/!/; - at 3234208
#181111 18:32:33 server id 1 end_log_pos 3234239 CRC32 0x2bce270a Xid = 32864
COMMIT/!/; - at 3234239
#181111 18:32:33 server id 1 end_log_pos 3234262 CRC32 0xe9d0f23e Stop
DELIMITER ; - End of log file
ROLLBACK /* added by mysqlbinlog */;
/!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE/;
/!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0/;
Upgraded to 10.3.10 and same problem...
Trying to completely remove instance now.
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...
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.
It seems to be working okay for me, tried a few times:
11 Query START TRANSACTION11 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 COMMIT12 Query shutdown| 506 || 506 || @@version || 10.3.8-MariaDB-log |Could you please provide SHOW CREATE for the table, maybe there is something in there?