Bug #26055 Falcon: Error 1020 with only one connection
Submitted: 3 Feb 2007 22:15 Modified: 26 Apr 2007 10:58
Reporter: Peter Gulutzan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:5.2.2-falcon-alpha-debug-log OS:Linux (SUSE 10.0 / 64-bit)
Assigned to: CPU Architecture:Any

[3 Feb 2007 22:15] Peter Gulutzan
Description:
I created a Falcon table with one CHAR() UTF8 column, unindexed.
I inserted 2652160 rows.
Later, I tried to delete many rows, and saw:
ERROR 1020 (HY000): Record has changed since last read in table 'tu'

This differs from the other bugs with error=1020
(Bug#24970, Bug#25557) in a major way:
there is only one connection.
So no other transaction can have "changed" anything.

How to repeat:
delimiter //
set @@autocommit=0//
drop table tu//
drop procedure pu//
set @@sql_mode=traditional//
set names utf8//
create table tu (s1 varchar(10) character set utf8) engine=falcon//
create procedure pu () begin declare v1 int default 0; declare continue handler for sqlexception begin end; while v1 <= 16777216 do if v1 mod 1000 = 0 then select v1; commit; end if; set @v = concat('insert into tu values (0x',hex(v1),')'); prepare stmt1 from @v; execute stmt1; set v1 = v1 + 1; end while; end//
call pu()//

The above procedure takes about 4 hours.

Take down the server. Start it again.
Try to delete all rows that are more than one character long.
This is the result I get:

mysql> set @@autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> delete from tu where char_length(s1)>1;
ERROR 1020 (HY000): Record has changed since last read in table 'tu'
[4 Feb 2007 20:41] Hakan Küçükyılmaz
Can't repeat first scenario. Tried on Linux 64-bit with 8GB RAM SLES 9, change set  1.2419.1.1, 2007-02-02 .

| 16776000 |
+----------+
1 row in set (2 hours 11 min 32.22 sec)

+----------+
| v1       |
+----------+
| 16777000 |
+----------+
1 row in set (2 hours 11 min 32.69 sec)

Query OK, 1 row affected (2 hours 11 min 32.80 sec)

mysql> commit//
Query OK, 0 rows affected (0.00 sec)

mysql> Bye
hakan@lu0010:~> mysqladmin -uroot shutdown

After restarting mysqld

mysql>  set @@autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> delete from tu where char_length(s1)>1;
Query OK, 2586625 rows affected (38.34 sec)

However, SELECT count(*) looks odd:

mysql> select count(*) from tu;
+----------+
| count(*) |
+----------+
|    65536 |
+----------+
1 row in set (2.83 sec)

Regards, Hakan
[4 Feb 2007 21:16] Peter Gulutzan
After a successful DELETE, SELECT COUNT(*) should say 65536.
So this is apparently hard to repeat.
I start mysqld with --user=root --skip-networking --log-bin=/tmp/tmp.
After I start the client, these are my variable settings:
mysql> show variables like '%falcon%';
+--------------------------+----------+
| Variable_name            | Value    |
+--------------------------+----------+
| falcon_log_dir           |          |
| falcon_max_record_memory | 20971520 |
| falcon_min_record_memory | 0        |
| falcon_page_cache_size   | 4194304  |
| falcon_log_mask          | 0        |
| falcon_debug_server      | OFF      |
| falcon_page_size         | 4096     |
| have_falcon              | YES      |
+--------------------------+----------+
8 rows in set (0.04 sec)

Perhaps there is some setting that allows deletion
of more than 1 million rows. I know that if I can
delete smaller numbers by adding "AND s1 < 'b'" etc.
in the WHERE clause.

I wonder what happens if, after deleting all rows,
one says:
alter table tu add column cp932 varchar(5);
update tu set cp932=s1;
alter table tu add column otto integer unique auto_increment;
alter table tu partition by range (otto) (partition p1 values less than (30000),
partition p2 values less than maxvalue); /* necessary */
update tu set cp932 = concat(cp932,'',cp932,' ',cp932,0x00);
create unique index itu on tu (cp932,s1,otto);
select * from tu where cp932 like 'a%'; /* NEW */
insert into tu (cp932) values (0x4141204120); 
insert into tu (cp932) values (0x41412041);
select * from tu where cp932 like 'a%';
[5 Feb 2007 1:07] Hakan Küçükyılmaz
I could verify this bug by using the settings proposed by Peter Gulutzan:

+----------+
| v1       |
+----------+
| 16777000 |
+----------+
1 row in set (2 hours 10 min 7.32 sec)

Query OK, 1 row affected (2 hours 10 min 7.42 sec)

mysql>
mysql> commit//
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from tu//
+----------+
| count(*) |
+----------+
|  2652161 |
+----------+
1 row in set (17.57 sec)

Shutdown mysqld and restart it.

hakan@lu0010:~> mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.2.2-falcon-alpha-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> set @@autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> delete from tu where char_length(s1)>1;
ERROR 1020 (HY000): Record has changed since last read in table 'tu'

mysql> show variables like '%falcon%';
+--------------------------+----------+
| Variable_name            | Value    |
+--------------------------+----------+
| falcon_log_dir           |          |
| falcon_max_record_memory | 20971520 |
| falcon_min_record_memory | 0        |
| falcon_page_cache_size   | 4194304  |
| falcon_log_mask          | 0        |
| falcon_debug_server      | OFF      |
| falcon_page_size         | 4096     |
| have_falcon              | YES      |
+--------------------------+----------+
8 rows in set (0.01 sec)

Best regards, Hakan
[18 Apr 2007 16:56] Hakan Küçükyılmaz
Does not crash anymore:

mysql> set @@autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> delete from tu where char_length(s1)>1;
Query OK, 2586624 rows affected (9 hours 24 min 3.97 sec)

mysql> select count(*) from tu;
+----------+
| count(*) |
+----------+
|    65536 |
+----------+
1 row in set (3.44 sec)

mysql> rollback;
Query OK, 0 rows affected (4.40 sec)

mysql> select count(*) from tu;
+----------+
| count(*) |
+----------+
|  2652160 |
+----------+
1 row in set (5.80 sec)

mysql>
[18 Apr 2007 21:05] Hakan Küçükyılmaz
The described problem does not occur anymore. However, the DELETE performance has optimization potential.

I am closing this report and opening a new one regarding the DELETE performance.
[21 Apr 2007 2:17] Peter Gulutzan
I confirm that I no longer see a crash.
[26 Apr 2007 10:58] MC Brown
A note has been added to the 6.0.0 changelog.