MySQL Bugs: #42518: Maria error HA_ERR_ROW_NOT_VISIBLE Row is not visible by the current transaction

Bug #42518	Maria error HA_ERR_ROW_NOT_VISIBLE Row is not visible by the current transaction
Submitted:	1 Feb 2009 14:51	Modified:	26 May 2010 17:51
Reporter:	Philip Stoev	Email Updates:
Status:	Unsupported	Impact on me:	None
Category:	MySQL Server: Maria storage engine	Severity:	S2 (Serious)
Version:	6.0-maria	OS:	Any
Assigned to:		CPU Architecture:	Any
Triage:	Triaged: D2 (Serious)

Description:
When executing a concurrent workload under Maria, some UPDATE statements fail with the following error:

1030 Got error 182 from storage engine

which translates to

HA_ERR_ROW_NOT_VISIBLE Row is not visible by the current transaction

In my humble opinion, this error should never be sent to the client. If an UPDATE statement should not see a certain row, then the UPDATE statement should either block or skip over, depending on the transaction isolation level.

How to repeat:
with the RQG:

$ perl runall.pl \
  --basedir=/build/bzr/6.0-maria/ \
  --engine=maria \
  --gendata=conf/replication_single_engine.zz \
  --grammar=conf/replication_simple.yy \
  --threads=2

This creates a fairly light workload with simple SQL statements, however the tables have numerous fields and indexes.

I ran the testcase of BUG#42519, and this error is the first abnormal one to appear:
# 14:11:06 Starting 10 processes, 100000 queries each, duration 3600 seconds.
# 14:11:08 Started periodic reporting process...
# 14:11:09 Query: INSERT INTO `E` ( `pk` ) VALUES ( 9 ) failed: 1062 Duplicate entry '%s' for key '%s'. Further errors of this kind will be suppressed.
# 14:11:12 Query: UPDATE `BB` SET `datetime_nokey` = 3 WHERE `datetime_key` = 1 LIMIT 4 failed: 1030 Got error 182 from storage engine

The debug trace shows this:
T@15   : | | | | | | | | <_ma_read_block_record
T@15   : | | | | | | | | >_ma_read_block_record2
T@15   : | | | | | | | | <_ma_read_block_record2
T@15   : | | | | | | | <maria_rnext_same
T@15   : | | | | | | | exit: handler::multi_range_read_next result 182
T@15   : | | | | | | <handler::multi_range_read_next
T@15   : | | | | | <QUICK_RANGE_SELECT::get_next
T@15   : | | | | | >handler::print_error
T@15   : | | | | | | enter: error: 182
T@15   : | | | | | | >my_error
T@15   : | | | | | | | my: nr: 1030  MyFlags: 0  errno: 2
T@15   : | | | | | | | >my_message_sql
T@15   : | | | | | | | | error: error: 1030  message: 'Got error 182 from storage engine'

This is probably one of the callers of _ma_read_block_record2() which forgets to ignore this error, and instead sends it up.

Hi Philip. Surprisingly the latest 6.0-maria does not exhibit the bug (I didn't expect this). However, there is a strange DBD::mysql message, please see blow (I'm using the latest mysql-test-extra-6.0):

Servers started, exiting
# 10:35:23 Starting
# 10:35:23  gentest.pl \
# 10:35:23  --gendata=conf/replication_single_engine.zz \
# 10:35:23  --engine=maria \
# 10:35:23  --threads=2 \
# 10:35:23  --queries=1000 \
# 10:35:23  --duration=3600 \
# 10:35:23  --dsn1=dbi:mysql:host=127.0.0.1:port=19306:user=root:database=test \
# 10:35:23  --grammar=conf/replication_simple.yy
# 10:35:23 Creating table table0_maria .
# 10:35:23 Creating table table0_maria_int_autoinc .
# 10:35:24 Creating table table0_maria_key_pk_parts_2 .
DBD::mysql::db do failed: Field in list of fields for partition function not found in table at gendata.pl line 369.
# 10:35:24 Unable to create table table0_maria_key_pk_parts_2, skipping...
# 10:35:24 Creating table table0_maria_key_pk_parts_2_int_autoinc .
# 10:35:25 Creating table table1_maria .
# 10:35:25 Creating table table1_maria_int_autoinc .
# 10:35:25 Creating table table1_maria_key_pk_parts_2 .
DBD::mysql::db do failed: Field in list of fields for partition function not found in table at gendata.pl line 369.
# 10:35:25 Unable to create table table1_maria_key_pk_parts_2, skipping...
# 10:35:25 Creating table table1_maria_key_pk_parts_2_int_autoinc .
# 10:35:26 Creating table table10_maria .
# 10:35:27 Creating table table10_maria_int_autoinc .
# 10:35:27 Creating table table10_maria_key_pk_parts_2 .
DBD::mysql::db do failed: Field in list of fields for partition function not found in table at gendata.pl line 369.
# 10:35:27 Unable to create table table10_maria_key_pk_parts_2, skipping...
# 10:35:27 Creating table table10_maria_key_pk_parts_2_int_autoinc .
# 10:35:28 Creating table table100_maria .
# 10:35:32 Creating table table100_maria_int_autoinc .
# 10:35:36 Creating table table100_maria_key_pk_parts_2 .
DBD::mysql::db do failed: Field in list of fields for partition function not found in table at gendata.pl line 369.
# 10:35:36 Unable to create table table100_maria_key_pk_parts_2, skipping...
# 10:35:36 Creating table table100_maria_key_pk_parts_2_int_autoinc .
# 10:35:39 Reporters: ErrorLog, Backtrace
# 10:35:40 Validators: ErrorMessageCorruption
# 10:35:40 Starting 2 processes, 1000 queries each, duration 3600 seconds.
# 10:35:40 Started periodic reporting process...
# 10:35:40 Query: INSERT INTO `table1_maria_key_pk_parts_2_int_autoinc` ( `int_unsigned_not_null` ) VALUES ( NULL ) failed: 1048 Column '%s' cannot be null. Further errors of this kind will be suppressed.
# 10:35:41 Query: INSERT INTO `table1_maria_key_pk_parts_2_int_autoinc` ( `int_unsigned_not_null` ) VALUES ( NULL ) failed: 1048 Column '%s' cannot be null. Further errors of this kind will be suppressed.
# 10:35:45 Query: UPDATE `table10_maria` SET `float` = 0 WHERE `set_utf8_not_null_key` = 'dvbhwbqmclxkddxyvtvnkvnecbtjnmvihfykuxiypxdyepdxfyprhiiavwokgkjxjfsuvxwqdrlgpbhmuvlqnrbpvpemmscawgnlspcgnurrvbvnkdltqv' failed: 1030 Got error %d from storage engine. Further errors of this kind will be suppressed.
# 10:36:18 Child process completed successfully.
# 10:36:18 Child process completed successfully.
# 10:36:23 Killing periodic reporting process with pid 7288...
# 10:36:28 Test completed successfully.
And, please see "%d" in "Got error %d" above: it's a bug to have %d instead of a real number, is the bug in runall or in the Server?

Guilhem, I believe the error is still there. The issue is that, in an overkilled effort to suppress duplicate error messages, I have removed the integer 182 from "Got error" and replaced it with "%d".

I will fix the RQG so that those errors are reported verbatim. I will also make them fatal so that the test does not report success when an error like this is encountered.

You are right, Philip. The error is still there, as I could see by starting mysqld with --debug, at some point there is in the debug trace:
T@9    : | | | | | | | | | | <pagecache_read
T@9    : | | | | | | | | | <_ma_read_block_record
T@9    : | | | | | | | | | >_ma_read_block_record2
T@9    : | | | | | | | | | <_ma_read_block_record2
T@9    : | | | | | | | | <maria_rnext_same
T@9    : | | | | | | | <ha_partition::handle_unordered_next
T@9    : | | | | | | | exit: handler::multi_range_read_next result 182
T@9    : | | | | | | <handler::multi_range_read_next
T@9    : | | | | | <QUICK_RANGE_SELECT::get_next
T@9    : | | | | | >ha_partition::print_error
T@9    : | | | | | | enter: error: 182
T@9    : | | | | | | >handler::print_error
T@9    : | | | | | | | enter: error: 182
T@9    : | | | | | | | >my_error
T@9    : | | | | | | | | my: nr: 1030  MyFlags: 0  errno: 0
T@9    : | | | | | | | | >my_message_sql
T@9    : | | | | | | | | | error: error: 1030  message: 'Got error 182 from storage engine'