Weird behaviour with batch and trigger(MariaDB)

Question

I found a weird issue involving mariadb. batch update from hibernate. the original question was added here : https://stackoverflow.com/questions/78204056/hibernate-sqlintegrityconstraintviolation-duplicate-data-entry-issue-after-upg?noredirect=1#comment138316709_78204056

table t_instancetest

CREATE TABLE `t_instancetest` (
    `RATEID` BIGINT(10) NOT NULL,
    `BID` VARCHAR(25) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `ASK` VARCHAR(25) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `MID` VARCHAR(25) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `UPDATEDDATE` DATETIME(6) NULL DEFAULT NULL,
    `INSTANCEUPDATEDDATE` DATETIME(6) NULL DEFAULT NULL,
    `UPDATEDBY` VARCHAR(30) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `CRUD` VARCHAR(1) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `CREATEDBY` VARCHAR(30) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `INSTANCEUPDATEDBY` VARCHAR(30) NULL DEFAULT NULL COLLATE 'utf8_bin',
    `LOCATIONID` INT(3) NOT NULL,
    PRIMARY KEY (`RATEID`, `LOCATIONID`) USING BTREE
)COLLATE='utf8_bin'
ENGINE=InnoDB
;

audit log

CREATE TABLE `t_datalog` (
    `Id` BIGINT(10) NOT NULL AUTO_INCREMENT,
    `RateId` BIGINT(10) NOT NULL,
    `CreatedDate` DATETIME(6) NOT NULL,
    PRIMARY KEY (`Id`) USING BTREE
     ))
COLLATE='utf8_bin'
ENGINE=InnoDB
AUTO_INCREMENT=232
;

TRIGGER (BEFORE UPDATE ) - but this field later removed to make it easier to test - and this trigger dropped.

 CREATE DEFINER=`USERADMIN`@`%` TRIGGER `TRG_BU_T_INSTANCE`. 
 BEFORE UPDATE ON `t_instance` FOR EACH ROW BEGIN 
   SET NEW.ATTRCHANGEID=UUID();
     END

TRIGGER (AFTER UPDATE)

CREATE DEFINER=`USERADMIN`@`%` TRIGGER `TRG_AU_T_INSTANCETEST` AFTER UPDATE ON `t_instancetest` FOR EACH ROW BEGIN
INSERT INTO `t_datalog` ( `RateId`, `CreatedDate`) VALUES (OLD.RATEID, sysdate());
 END

Batch update from application ( batchsize = 7)-as can be shown here, it update 7 different rateids

2024-05-10 12:31:59.814  INFO 3472 --- [nio-9012-exec-2] n.t.d.l.l.SLF4JQueryLoggingListener      : {"name":"reliableDataSource", "connection":3, "time":13, "success":true, "type":"Prepared", "batch":true, "querySize":1, "batchSize":7, "query":["update t_instancetest set ask=?, bid=?, createdby=?, crud=?, instanceupdateddate=?, locationId=?, mid=?, updatedby=?, updateddate=? where locationid=? and rateId=?"], "params":[["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7181","naga","2024-05-10 12:03:55.0","101","7181"], 
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7239","naga","2024-05-10 12:03:55.0","101","7239"],
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7254","naga","2024-05-10 12:03:55.0","101","7254"],
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7265","naga","2024-05-10 12:03:55.0","101","7265"],
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7370","naga","2024-05-10 12:03:55.0","101","7370"],
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7453","naga","2024-05-10 12:03:55.0","101","7453"],
["116.13","12.23","SYSTEM","U","2024-05-10 12:31:59.665","101","7643","naga","2024-05-10 12:03:55.0","101","7643"]]}

Mariadb logs , however showing we are only updating one record in t_instancetest and execute trigger 7 times on the same rateid. other rateid were not executed.

    #240509 17:27:01 server id 2  end_log_pos 127297238 CRC32 0x5e6a5fa7   Write_rows: table id 3067 flags: STMT_END_F
### UPDATE `reliabledb`.`t_instance`
### WHERE
###   @1=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='12.23' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @3='116.13' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @4='' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @5='2024-05-09 16:49:54.962888' /* DATETIME(6) meta=6 nullable=1 is_null=0 */
###   @6='2024-05-09 17:22:52.812000' /* DATETIME(6) meta=6 nullable=1 is_null=0 */
###   @7='naga' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @8='U' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @9='SYSTEM' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @10='naga' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @11=101 /* INT meta=0 nullable=0 is_null=0 */
### SET
###   @1=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='12.23' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @3='116.13' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @4='7181' /* VARSTRING(75) meta=75 nullable=1 is_null=0 */
###   @5='2024-05-09 16:49:54.962888' /* DATETIME(6) meta=6 nullable=1 is_null=0 */
###   @6='2024-05-09 17:27:01.116000' /* DATETIME(6) meta=6 nullable=1 is_null=0 */
###   @7='naga' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @8='U' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @9='SYSTEM' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @10='naga' /* VARSTRING(90) meta=90 nullable=1 is_null=0 */
###   @11=101 /* INT meta=0 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=98 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=99 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=100 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=101 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=102 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
### INSERT INTO `reliabledb`.`t_datalog`
### SET
###   @1=103 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=7181 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @3='2024-05-09 17:27:01.000000' /* DATETIME(6) meta=6 nullable=0 is_null=0 */
# Number of rows: 7
# at 127297238
#240509 17:27:01 server id 2  end_log_pos 127297269 CRC32 0xd7928418    Xid = 205571784
COMMIT/*!*/;

If we drop the trigger, the insertion completed normally (all record updated ). Also if we remove the batch, the behaviour the insertion will completed also. The issue only happened if batch size > 3 and trigger are in effect.

Anyone can share any idea on why this is happening? or maybe point to a mariadb bug that might interfere with this? It only happens for this table on the schema, where the other table are not affected.

version details:

mariadb 10.5
mariadb jdbc client 3.3.3 ( also tried with 2.7.4 )
spring boot ( java ) 2.7.18
hibernate 5.6.15

Rudy · Accepted Answer · 2024-05-16T07:31:17.780

seems the issue is related to the mariadb jdbc driver + maria db server itself.

which also affects batch update. the issue is also found by some other people eg : https://stackoverflow.com/questions/76430213/jooqs-batchinsert-doesnt-behave-as-expected-with-after-insert-trigger

Some points :

Issue happened since MariaDB has implemented a new bulk processing mode , together with new jdbc4.2
however this new bulk processing has an issue where combined with trigger ( after update / after insert )
There is workaround by putting the &useBulkStmts=false which, reverted the mode to the previous one and I have confirmed that the issue has no longer showing in our testcase. For the permanent fix, we have to wait for MariaDB.
There is no known workaround by changing the server global variables.

Weird behaviour with batch and trigger(MariaDB)

1 Answers1