Duplicate keys with table_open_cache_instances > 1

Bug #1349915 reported by Peter Boros
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Status tracked in 5.6
5.5
Invalid
Undecided
Unassigned
5.6
Fix Committed
High
Unassigned

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_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.

Revision history for this message
Peter Boros (pboros) wrote :

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

Revision history for this message
Peter Boros (pboros) wrote :

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).

Revision history for this message
Peter Boros (pboros) wrote :

Modified insert.lua for sysbench.

Revision history for this message
Jay Janssen (jay-janssen) wrote :

What version was this?

Revision history for this message
Peter Boros (pboros) wrote :

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

Revision history for this message
Seppo Jaakola (seppo-jaakola) wrote :

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

Revision history for this message
Peter Boros (pboros) wrote : Re: [Bug 1349915] Re: Duplicate keys with table_open_cache_instances > 1
Download full text (4.2 KiB)

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...

Read more...

Revision history for this message
Seppo Jaakola (seppo-jaakola) wrote :

so maybe this manifests in PXC only

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

@PeterB, Valerii,

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

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (4.0 KiB)

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...

Read more...

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

@Nil,

Can you check with RPM in experimental repo:

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

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

@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.

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

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]#

Revision history for this message
Krunal Bauskar (krunal-bauskar) wrote :

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

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.