Duplicate keys with table_open_cache_instances > 1

[Peter Boros]

If all the nodes are written, and table_open_cache_instances is > 1, the following thing happens:
# sysbench --test=/opt/sysbench/sysbench/tests/db/insert_autoinc.lua --oltp-table-size=100000 --oltp-tables-count=1 --num-threads=32 --mysql-host=127.0.0.1 --mysql-user=sbtest --mysql-password=sbtest --mysql-port=3307 --report-interval=1 --max-requests=0 --max-time=0 run
WARNING: Both max-requests and max-time are 0, running endless test
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 32
Report intermediate results every 1 second(s)
Random number generator seed is 0 and will be ignored

Threads started!

[ 1s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 267.06, response time: 158.38ms (95%)
[ 2s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 219.00, response time: 202.14ms (95%)
[ 3s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 244.00, response time: 167.30ms (95%)
[ 4s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 253.00, response time: 140.89ms (95%)
[ 5s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 280.00, response time: 141.01ms (95%)
[ 6s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 271.00, response time: 150.66ms (95%)
[ 7s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 270.00, response time: 152.70ms (95%)
[ 8s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 272.00, response time: 147.67ms (95%)
[ 9s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 295.00, response time: 138.17ms (95%)
[ 10s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 250.00, response time: 149.71ms (95%)
ALERT: failed to execute MySQL query: `INSERT INTO sbtest1 (k, c, pad) VALUES (50004, '89929769380-86884577498-44821537687-01291340378-94877073036-86937829586-68219997234-17550189837-39233820479-95928832298', '24150738052-65325743530-90033340743-93376107484-35784626790')`:
ALERT: Error 1062 Duplicate entry '342031' for key 'PRIMARY'
FATAL: failed to execute function `event': (null)

It doesn't happen if table_open_cache_instances is 1 (default), or if I write only to one node. In order to produce this, a custom lua is needed for sysbench:

# cat sysbench/tests/db/insert_autoinc.lua
pathtest = string.match(test, "(.*/)") or ""

dofile(pathtest .. "common.lua")

function thread_init(thread_id)
   set_vars()
end

function event(thread_id)
   local table_name
   local i
   local c_val
   local k_val
   local pad_val

   table_name = "sbtest".. sb_rand_uniform(1, oltp_tables_count)

   if (oltp_auto_inc) then
      i = 0
   else
      i = sb_rand_uniq(1, oltp_table_size)
   end
   k_val = sb_rand(1, oltp_table_size)
   c_val = sb_rand_str([[
###########-###########-###########-###########-###########-###########-###########-###########-###########-###########]])
   pad_val = sb_rand_str([[
###########-###########-###########-###########-###########]])

   rs = db_query("INSERT INTO " .. table_name .. " (k, c, pad) VALUES " .. string.format("(%d, '%s', '%s')", k_val, c_val, pad_val))

   db_disconnect()
end

There are 2 changes compared to insert.lua:
- The id column is removed from it and we let auto_increment to handle that.
- db_disconnect is at the end, so sysbench will reconnect for every transaction.

Locally, I had to set
echo 1000 > /proc/sys/net/ipv4/tcp_max_tw_buckets
so I don't run into TCP/IP port exhaustion.

[Peter Boros (pboros)]

The Test.java produces the bug earlier then sysbench.

Usage: download mysql connector jar
javac Test.java (creates Test.class and Test$Worker.class)
jar cvf test.jar Test*.*
java -cp test.jar:./mysql-connector-java-5.1.25.jar Test

[Peter Boros (pboros)]

In the previous Test.java, replace this
private static String[] DEFAULT_SERVERS = { "pxc1" };
with the hosts to connect to, in case of 3 nodes I used:
private static String[] DEFAULT_SERVERS = { "pxc1", "pxc2", "pxc3" };

The bug is present with using a load balancer as well (the above sysbench solution used haproxy to connect to all nodes).

[Peter Boros (pboros)]

Modified insert.lua for sysbench.

[Jay Janssen (jay-janssen)]

What version was this?

[Peter Boros (pboros)]

Latest: Server version: 5.6.19-67.0-56-log Percona XtraDB Cluster (GPL), Release rel67.0, Revision 824, WSREP version 25.6, wsrep_25.6.r4111

[Seppo Jaakola (seppo-jaakola)]

Tried the Test.java method, but cannot reproduce this issue with Galera Cluster (dev version 5.6.20)

[Peter Boros (pboros)]

XtraDB Cluster 5.6.19-67.0

On Tue, Jul 29, 2014 at 5:48 PM, Jay Janssen <email address hidden> wrote:
> What version was this?
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1349915
>
> Title:
> Duplicate keys with table_open_cache_instances > 1
>
> Status in Percona XtraDB Cluster - HA scalable solution for MySQL:
> New
>
> Bug description:
> If all the nodes are written, and table_open_cache_instances is > 1, the following thing happens:
> # sysbench --test=/opt/sysbench/sysbench/tests/db/insert_autoinc.lua --oltp-table-size=100000 --oltp-tables-count=1 --num-threads=32 --mysql-host=127.0.0.1 --mysql-user=sbtest --mysql-password=sbtest --mysql-port=3307 --report-interval=1 --max-requests=0 --max-time=0 run
> WARNING: Both max-requests and max-time are 0, running endless test
> sysbench 0.5: multi-threaded system evaluation benchmark
>
> Running the test with following options:
> Number of threads: 32
> Report intermediate results every 1 second(s)
> Random number generator seed is 0 and will be ignored
>
>
> Threads started!
>
> [ 1s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 267.06, response time: 158.38ms (95%)
> [ 2s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 219.00, response time: 202.14ms (95%)
> [ 3s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 244.00, response time: 167.30ms (95%)
> [ 4s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 253.00, response time: 140.89ms (95%)
> [ 5s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 280.00, response time: 141.01ms (95%)
> [ 6s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 271.00, response time: 150.66ms (95%)
> [ 7s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 270.00, response time: 152.70ms (95%)
> [ 8s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 272.00, response time: 147.67ms (95%)
> [ 9s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 295.00, response time: 138.17ms (95%)
> [ 10s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 250.00, response time: 149.71ms (95%)
> ALERT: failed to execute MySQL query: `INSERT INTO sbtest1 (k, c, pad) VALUES (50004, '89929769380-86884577498-44821537687-01291340378-94877073036-86937829586-68219997234-17550189837-39233820479-95928832298', '24150738052-65325743530-90033340743-93376107484-35784626790')`:
> ALERT: Error 1062 Duplicate entry '342031' for key 'PRIMARY'
> FATAL: failed to execute function `event': (null)
>
> It doesn't happen if table_open_cache_instances is 1 (default), or if
> I write only to one node. In order to produce this, a custom lua is
> needed for sysbench:
>
> # cat sysbench/tests/db/insert_autoinc.lua
> pathtest = string.match(test, "(.*/)") or ""
>
> dofile(pathtest .. "common.lua")
>
> function thread_init(thread_id)
> set_vars()
> end
>
> function event(thread_id)
> local table_name
> local i
> local c_val
> local k_val
> local pad_val
>
> table_name = "sbtest".. sb_rand_uniform(1, oltp_tables_count)
>
> if (oltp_auto_inc) then
> i = 0
> else
> i = sb_rand_u...

[Seppo Jaakola (seppo-jaakola)]

so maybe this manifests in PXC only

[Raghavendra D Prabhu (raghavendra-prabhu)]

@PeterB, Valerii,

5.6.20 PXC rpm are in experimental repo for testing - http://jenkins.percona.com/experimental/CENTOS/percona-experimental.repo

[Nilnandan Joshi (nilnandan-joshi)]

Invalid for 5.5 as this variable was added in MySQL 5.6.6.
http://dev.mysql.com/doc/refman/5.6/en/server-system-variables.html#sysvar_table_open_cache_instances

[Nilnandan Joshi (nilnandan-joshi)]

Able to reproduce with PXC 5.6.19, but once...when it failed and I have started again it didn't give error.

root@deb-pxc56-1:~/sysbench/sysbench# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 6
Server version: 5.6.19-67.0-56-log Percona XtraDB Cluster (GPL), Release 25.6, wsrep_25.6.r4111

...
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show global variables like 'table_open_cache%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| table_open_cache | 2000 |
| table_open_cache_instances | 8 |
+----------------------------+-------+
2 rows in set (0.00 sec)

mysql> quit
Bye
root@deb-pxc56-1:~/sysbench/sysbench# ./sysbench --test=/root/sysbench/sysbench/tests/db/insert_autoinc.lua --oltp-table-size=100000 --oltp-tables-count=1 --num-threads=32 --mysql-host=127.0.0.1 --mysql-user=root --mysql-password=root --mysql-port=3306 --report-interval=1 --max-requests=0 --max-time=0 run
WARNING: Both max-requests and max-time are 0, running endless test
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 32
Report intermediate results every 1 second(s)
Random number generator seed is 0 and will be ignored

Threads started!

ALERT: failed to execute MySQL query: `INSERT INTO sbtest1 (k, c, pad) VALUES (49870, '69429576205-87925969202-02408199676-02281819182-93380360381-84587501731-92830026416-93404212567-05243222892-12376805095', '12147864779-36258834409-01700703135-41171421152-05431759726')`:
ALERT: Error 1062 Duplicate entry '212495' for key 'PRIMARY'
FATAL: failed to execute function `event': (null)
[ 1s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 50.67, response time: 600.80ms (95%)
root@deb-pxc56-1:~/sysbench/sysbench#

root@deb-pxc56-1:~/sysbench/sysbench# ./sysbench --test=/root/sysbench/sysbench/tests/db/insert_autoinc.lua --oltp-table-size=100000 --oltp-tables-count=1 --num-threads=32 --mysql-host=127.0.0.1 --mysql-user=root --mysql-password=root --mysql-port=3306 --report-interval=1 --max-requests=0 --max-time=0 run
WARNING: Both max-requests and max-time are 0, running endless test
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 32
Report intermediate results every 1 second(s)
Random number generator seed is 0 and will be ignored

Threads started!

[ 1s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 0.00, response time: 0.00ms (95%)
[ 2s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 34.00, response time: 1686.45ms (95%)
[ 3s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 18.00, response time: 831.84ms (95%)
[ 4s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 32.00, response time: 1796.94ms (95%)
[ 5s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 30.00, response time: 1146.91ms (95%)
[ 6s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 2.00, response time: 1131.23ms (95%)
[ 7s] threads: 32, tps: 0.00, reads/s: 0.00, writes/s: 32.03, response time: 1821.85ms (95%)
[ 8s...

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Nil,

Can you check with RPM in experimental repo:

http://jenkins.percona.com/experimental/CENTOS/percona-experimental.repo

[Nilnandan Joshi (nilnandan-joshi)]

@Raghu,

After installing experimental repo, I'm getting this.

[root@percona-pxc55-1 mysql]# su -c 'yum list Percona-Xtradb-Cluster-56'
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
 * base: centos.aol.in
 * epel: kartolo.sby.datautama.net.id
 * extras: centos.aol.in
 * updates: centos.aol.in
Available Packages
Percona-XtraDB-Cluster-56.x86_64 1:5.6.19-25.6.828.el6 percona-testing
[root@percona-pxc55-1 mysql]#

Do you want me to test with this? or I should wait for 5.6.20? Please let me know.

[Nilnandan Joshi (nilnandan-joshi)]

Checked in PXC 5.6.20 (testing) with sysbench 0.5, table_open_cache_instances=8 and writing in all nodes. I couldn't reproduce that error. Sharing one of node result here.

[root@percona-pxc56-1 db]# sysbench --test=/usr/share/doc/sysbench/tests/db/insert_autoinc.lua --oltp-table-size=100000 --oltp-tables-count=1 --num-threads=256 --mysql-host=127.0.0.1 --mysql-user=root --mysql-password=root --mysql-port=3306 --report-interval=1 --max-requests=0 --max-time=180 run
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 256
Report intermediate results every 1 second(s)
Random number generator seed is 0 and will be ignored

Threads started!

[ 1s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 38.76, response time: 913.27ms (95%)
[ 2s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 42.00, response time: 1922.71ms (95%)
[ 3s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 36.99, response time: 2847.57ms (95%)
[ 4s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 37.00, response time: 3864.34ms (95%)
[ 5s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 24.00, response time: 4527.38ms (95%)
[ 6s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 6.00, response time: 5900.62ms (95%)
...
[ 184s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 0.00, response time: 0.00ms (95%)
[ 185s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 39.00, response time: 9345.01ms (95%)
[ 186s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 28.00, response time: 8206.52ms (95%)
[ 187s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 45.00, response time: 12341.02ms (95%)
[ 188s] threads: 256, tps: 0.00, reads/s: 0.00, writes/s: 48.00, response time: 12583.49ms (95%)
OLTP test statistics:
    queries performed:
        read: 0
        write: 5311
        other: 0
        total: 5311
    transactions: 0 (0.00 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 5311 (28.24 per sec.)
    other operations: 0 (0.00 per sec.)

General statistics:
    total time: 188.0751s
    total number of events: 5311
    total time taken by event execution: 47228.6313s
    response time:
         min: 17.63ms
         avg: 8892.61ms
         max: 15962.30ms
         approx. 95 percentile: 12337.32ms

Threads fairness:
    events (avg/stddev): 20.7461/0.55
    execution time (avg/stddev): 184.4868/2.44

[root@percona-pxc56-1 db]#

[Krunal Bauskar (krunal-bauskar)]

This issue is not reproducible on latest 5.6. Please upgrade.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1014