[MDEV-6817] query cache bug (resturning inconsistent/old result set) with aria table parallel inserts, row format = page - JIRA

Details

Type: Bug
Status: Stalled
Priority: Critical
Resolution: Unresolved
Affects Version/s: 5.3.12, 10.1, 10.0, 5.5
Fix Version/s: 10.1, 10.0
Component/s: Query Cache, Storage Engine - Aria
Labels:

Sprint:
10.0.20

Description

hi guys, i'm running a stress test with query cache and aria...
the table:

CREATE TABLE `errors` (
	`id1` INT(11) NOT NULL DEFAULT '0',
	`id2` INT(11) NOT NULL DEFAULT '0',
	`err_id` INT(11) NOT NULL DEFAULT '0',
	`datahora` DECIMAL(22,7) NOT NULL DEFAULT '0.0000000',
	`erro` LONGBLOB NOT NULL,
	PRIMARY KEY (`id1`, `id2`, `err_id`)
)
COLLATE='latin1_swedish_ci'
ENGINE=Aria;
(using page table type!)

i startup a php script:

<?php
$pid=pcntl_fork();
if($pid==0) $pid=pcntl_fork();
if($pid==0) $pid=pcntl_fork();
// three different process


// connect to database
$conn=mysql_connect(/* connection parameters */);
mysql_select_db(/*select database*/);

// and start a infinite loop
$contador=0;
while(1){
		$SQL=	"SELECT MAX(err_id) FROM errors ".
			"WHERE id1=1 AND id2=2";
IF($contador%1000==0 && $contador>1000) echo "\n$SQL\n";
		$tmp_tbl=mysql_query($SQL);
		$err_id=mysql_result($tmp_tbl,0,0);
IF($contador%1000==0 && $contador>1000) echo "\n$err_id\n";
		mysql_free($tmp_tbl);
		$err_id++;if($err_id<=0) $err_id=1;
		$SQL=	"INSERT INTO errors (".
				"id1,id2,err_id,datahora,erro".
			") VALUES (".
				"1,2,$err_id,'".microtime(1)."','test '".
			")";
		$ok=mysql_query($SQL); /* autocommit = 1 */
		
		if($ok){
			$contador=0;
			continue;
		}
		$contador++;
		usleep(500); // wait a bit...
}

aria variables:

Variable_name	Value
aria_block_size	8192
aria_checkpoint_interval	30
aria_checkpoint_log_activity	1048576
aria_force_start_after_recovery_failures	0
aria_group_commit	none
aria_group_commit_interval	0
aria_log_file_size	1073741824
aria_log_purge_type	immediate
aria_max_sort_file_size	9223372036853727232
aria_page_checksum	ON
aria_pagecache_age_threshold	300
aria_pagecache_buffer_size	134217728
aria_pagecache_division_limit	100
aria_recover	NORMAL
aria_repair_threads	1
aria_sort_buffer_size	268434432
aria_stats_method	nulls_unequal
aria_sync_log_dir	NEWFILE
aria_used_for_temp_tables	ON

autocommit=1
concurrent_insert isn't a problem, i tested with 0,1,2 this give the same error

–
what i think is happen?
at query cache code there's a consideration about when or when not include the query at query cache, while a insert and another aria table is invalidated and a "select" query execute:

time ->
-----INSERT-------
---SELECCCCCCT--- (cached after invalidation - shoudn't be cached)
---------------------SELECT ---- (got from query cache, wrong query cache value)

the value of the new insert field err_id isn't updated at the right time, in other words when i connect with a externall tool and set autocommit=0 (to get a different query cache flag, or use SQL_NO_CACHE) i see that the err_id is different from err_id of php script

in other words
1)the table wasn't invalidated correctly
2)the query was cached in a state that aria engine should report to don't cache (concurrent insert? page flush? anything like a buffer or cache being used while updating table?)

could we recheck if the aria engine invalidation is ok or not?
i will test again with myisam, and after innodb
—
no problem with innodb
no problem with myisam
no problem with aria using row_format fixed/dynamic, only with aria-page

Gliffy Diagrams

Attachments

Issue Links

is blocked by

MDEV-7314 Concurrent "INSERT INTO table SELECT MAX(id)+1 FROM table" are hitting deadlocks on Aria tables using ROW_FORMAT=PAGE

Closed

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

roberto spadim added a comment - 2014-09-30 21:22

testing with myisam (the real myisam engine, not the aria myisam like) and fixed/dynamic types
no problem

Show

roberto spadim added a comment - 2014-09-30 21:22 testing with myisam (the real myisam engine, not the aria myisam like) and fixed/dynamic types no problem

20 older comments

Hide

Permalink

Oleksandr Byelkin added a comment - 2015-04-16 10:28

second test works, but produce expected results...

Show

Oleksandr Byelkin added a comment - 2015-04-16 10:28 second test works, but produce expected results...

Hide

Permalink

Elena Stepanova added a comment - 2015-04-16 15:50

Modified and cleaned up test case

<?php

$pid=pcntl_fork();

// connect to database
$conn=mysql_connect('127.0.0.1:3306','root');

// create an Aria table
mysql_query("DROP DATABASE IF EXISTS mdev6817");
mysql_query("CREATE DATABASE mdev6817");
mysql_select_db('mdev6817');
mysql_query("CREATE TABLE IF NOT EXISTS t1 (id INT NOT NULL DEFAULT '0', PRIMARY KEY (id)) ENGINE=Aria");

// enable query cache
mysql_query("SET GLOBAL query_cache_type = 1");
mysql_query("SET GLOBAL query_cache_size = 1024*1024*256");

// this is just for further logging
$con_id=mysql_result(mysql_query("SELECT CONNECTION_ID()"),0,0);

// $counter will count sequential SELECT MAX() queries executed after the last successful INSERT 
$counter=0;

// and start a infinite loop
while(1){
		$SQL=	"SELECT MAX(id) FROM t1";
		$tmp_tbl=mysql_query($SQL);
		$id=mysql_result($tmp_tbl,0,0);
		mysql_free_result($tmp_tbl);
		// 1000 is for throttling
		if($counter%1000==0 && $counter>1000) {
			echo "Connection $con_id: Executed $counter 'SELECT MAX(id)...' queries, result is $id\n";
		}
		$id++; 
		// probably to avoid overflow? It was like that in the initial test, keeping as is
		if($id<=0) $id=1;

		$SQL=	"INSERT INTO t1 VALUES ($id)";
		$ok=mysql_query($SQL); /* autocommit = 1 */
		
		if($ok){
			echo "Connection $con_id: Successfully inserted id=$id\n";
			$counter=0;
			continue;
		}
		$counter++;
		usleep(500); // wait a bit...
}

Expected result if there is no bug

Connection 7: Successfully inserted id=1
Connection 8: Successfully inserted id=2
Connection 8: Successfully inserted id=3
...
Connection 7: Successfully inserted id=124
Connection 7: Successfully inserted id=125
...

Connection numbers can vary.

Example of the actual result, observed on all MariaDB versions

Connection 12: Successfully inserted id=1
Connection 11: Successfully inserted id=2
Connection 11: Successfully inserted id=3
Connection 12: Executed 2000 'SELECT MAX(id)...' queries, result is 2
Connection 11: Executed 2000 'SELECT MAX(id)...' queries, result is 2
Connection 12: Executed 3000 'SELECT MAX(id)...' queries, result is 2
Connection 11: Executed 3000 'SELECT MAX(id)...' queries, result is 2
Connection 12: Executed 4000 'SELECT MAX(id)...' queries, result is 2
Connection 11: Executed 4000 'SELECT MAX(id)...' queries, result is 2
Connection 11: Executed 5000 'SELECT MAX(id)...' queries, result is 2
Connection 12: Executed 5000 'SELECT MAX(id)...' queries, result is 2
...

Connection numbers and the result value can vary, the important part is that the result remains the same.
The idea is that at some point SELECT starts returning a smaller value than currently exists in the table, no matter how many times you re-run the query.
Only observed with the query cache.

Show

Elena Stepanova added a comment - 2015-04-16 15:50 Modified and cleaned up test case <?php $pid=pcntl_fork(); // connect to database $conn=mysql_connect('127.0.0.1:3306','root'); // create an Aria table mysql_query( "DROP DATABASE IF EXISTS mdev6817" ); mysql_query( "CREATE DATABASE mdev6817" ); mysql_select_db('mdev6817'); mysql_query( "CREATE TABLE IF NOT EXISTS t1 (id INT NOT NULL DEFAULT '0', PRIMARY KEY (id)) ENGINE=Aria" ); // enable query cache mysql_query( "SET GLOBAL query_cache_type = 1" ); mysql_query( "SET GLOBAL query_cache_size = 1024*1024*256" ); // this is just for further logging $con_id=mysql_result(mysql_query( "SELECT CONNECTION_ID()" ),0,0); // $counter will count sequential SELECT MAX() queries executed after the last successful INSERT $counter=0; // and start a infinite loop while (1){ $SQL= "SELECT MAX(id) FROM t1" ; $tmp_tbl=mysql_query($SQL); $id=mysql_result($tmp_tbl,0,0); mysql_free_result($tmp_tbl); // 1000 is for throttling if ($counter%1000==0 && $counter>1000) { echo "Connection $con_id: Executed $counter 'SELECT MAX(id)...' queries, result is $id\n" ; } $id++; // probably to avoid overflow? It was like that in the initial test, keeping as is if ($id<=0) $id=1; $SQL= "INSERT INTO t1 VALUES ($id)" ; $ok=mysql_query($SQL); /* autocommit = 1 */ if ($ok){ echo "Connection $con_id: Successfully inserted id=$id\n" ; $counter=0; continue ; } $counter++; usleep(500); // wait a bit... } Expected result if there is no bug Connection 7: Successfully inserted id=1 Connection 8: Successfully inserted id=2 Connection 8: Successfully inserted id=3 ... Connection 7: Successfully inserted id=124 Connection 7: Successfully inserted id=125 ... Connection numbers can vary. Example of the actual result, observed on all MariaDB versions Connection 12: Successfully inserted id=1 Connection 11: Successfully inserted id=2 Connection 11: Successfully inserted id=3 Connection 12: Executed 2000 'SELECT MAX(id)...' queries, result is 2 Connection 11: Executed 2000 'SELECT MAX(id)...' queries, result is 2 Connection 12: Executed 3000 'SELECT MAX(id)...' queries, result is 2 Connection 11: Executed 3000 'SELECT MAX(id)...' queries, result is 2 Connection 12: Executed 4000 'SELECT MAX(id)...' queries, result is 2 Connection 11: Executed 4000 'SELECT MAX(id)...' queries, result is 2 Connection 11: Executed 5000 'SELECT MAX(id)...' queries, result is 2 Connection 12: Executed 5000 'SELECT MAX(id)...' queries, result is 2 ... Connection numbers and the result value can vary, the important part is that the result remains the same. The idea is that at some point SELECT starts returning a smaller value than currently exists in the table, no matter how many times you re-run the query. Only observed with the query cache.

Hide

Permalink

Oleksandr Byelkin added a comment - 2015-06-10 13:42

repeatable with --debug

Show

Oleksandr Byelkin added a comment - 2015-06-10 13:42 repeatable with --debug

Hide

Permalink

Oleksandr Byelkin added a comment - 2015-06-16 13:22

According to the log, the INSERT of highest id invalidated value in QC before ending internal transaction inside ARIA engine.
At the same time in other thread we was getting MAX() value and as far as the above transaction is not ended it got old value of MAX which was written to QC where it stay...

I also checked that non cached query returns correct value (got before cached).

Show

Oleksandr Byelkin added a comment - 2015-06-16 13:22 According to the log, the INSERT of highest id invalidated value in QC before ending internal transaction inside ARIA engine. At the same time in other thread we was getting MAX() value and as far as the above transaction is not ended it got old value of MAX which was written to QC where it stay... I also checked that non cached query returns correct value (got before cached).

Hide

Permalink

Oleksandr Byelkin added a comment - 2015-06-16 16:40

Proof of concept patch with invalidating locked for write tables on close thread tables for INSERT (it is problem of INSERT only) works.

Now it is time how to do it in a 'nice' way without big performance impact.

Show

Oleksandr Byelkin added a comment - 2015-06-16 16:40 Proof of concept patch with invalidating locked for write tables on close thread tables for INSERT (it is problem of INSERT only) works. Now it is time how to do it in a 'nice' way without big performance impact.

query cache bug (resturning inconsistent/old result set) with aria table parallel inserts, row format = page

Details

Description

Gliffy Diagrams

Attachments

Issue Links

Activity

People

Dates

Agile