Bug #35081 mysqld hangs for mysqlslap test with concurrency >1
Submitted: 5 Mar 2008 13:34 Modified: 13 Mar 2008 21:33
Reporter: Chandrashekhar Marathe Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.1.22-rc OS:Linux (RHEL5)
Assigned to: CPU Architecture:Any

[5 Mar 2008 13:34] Chandrashekhar Marathe
Description:
System Details
- mysqld-5.1.22-rc compiled from source.
- RHEL5 system

output:
Benchmark
        Running for engine MEMORY
        Average number of seconds to run all queries: 0.544 seconds
        Minimum number of seconds to run all queries: 0.458 seconds
        Maximum number of seconds to run all queries: 0.982 seconds
        Number of clients running queries: 1
        Average number of queries per client: 5000

Thus, the test for concurrency 1 passes but the one for 10 does not.

2. Mysqld details.

2.1 show processlist
mysql> show processlist;
+----+-------------+----------------+-----------+-------------+------+-----------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
| Id | User        | Host           | db        | Command     | Time | State                                                                 | Info                                                                                                 |
+----+-------------+----------------+-----------+-------------+------+-----------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
|  1 | system user |                | NULL      | Connect     |  597 | Waiting for master to send event                                      | NULL                                                                                                 |
|  2 | system user |                | NULL      | Connect     |  597 | Has read all relay log; waiting for the slave I/O thread to update it | NULL                                                                                                 |
| 14 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,614980131,2027947119,'4xMpYR8w8o74pPs3Q0ZXgAAzy9rtNaOJOe0wx8k5pj9e01ZJu7 |
| 15 | monty       | localhost      | mysqlslap | Query       |  574 | query end                                                             | SELECT intcol1,intcol2,charcol1,charcol2,charcol3 FROM t1 WHERE id =  '77'                           |
| 16 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,2126558185,773273718,'Y88N07to033m2XEIzHzMJsHuXTL2GeCheC4WJqIClDqol4ycMp |
| 17 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,2101913295,1100418235,'XQ0K9x30cYaFq2RvMZzKHKgmxy4uKBpreh4fX7f7XEEM8a9Nz |
| 18 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | SELECT intcol1,intcol2,charcol1,charcol2,charcol3 FROM t1 WHERE id =  '85'                           |
| 19 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,614980131,2027947119,'4xMpYR8w8o74pPs3Q0ZXgAAzy9rtNaOJOe0wx8k5pj9e01ZJu7 |
| 20 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,614980131,2027947119,'4xMpYR8w8o74pPs3Q0ZXgAAzy9rtNaOJOe0wx8k5pj9e01ZJu7 |
| 21 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | SELECT intcol1,intcol2,charcol1,charcol2,charcol3 FROM t1 WHERE id =  '87'                           |
| 22 | monty       | localhost      | mysqlslap | Query       |  574 | Locked                                                                | INSERT INTO t1 VALUES (NULL,1839719074,1147388315,'jbPuYPJuWuAF3FKMtuKwCtCBdruTJKwuvLhKms6Hm9OhOlwHX |
| 23 | monty       | localhost      | mysqlslap | Query       |  574 | update                                                                | INSERT INTO t1 VALUES (NULL,1233983202,789373855,'jdtPbBILRQyiu7nZN3RdI96aQOP4Y0z7dlO4wbQF1OpvYdLngg |
| 24 | monty       | sqldemo1:42629 | NULL      | Binlog Dump |  545 | Has sent all binlog to slave; waiting for binlog to be updated        | NULL                                                                                                 |
| 26 | monty       | localhost      | NULL      | Query       |    0 | NULL                                                                  | show processlist                                                                                     |
+----+-------------+----------------+-----------+-------------+------+-----------------------------------------------------------------------+------------------------------------------------------------------------------------------------------+
14 rows in set (0.00 sec)

2.2
pstack output (some interesting threads)

Thread 13 (Thread -1588188272 (LWP 25304)):
#0  0x00892402 in __kernel_vsyscall ()
#1  0x00a40146 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#2  0x0856b579 in wait_for_lock ()
#3  0x0856bce3 in thr_multi_lock ()
#4  0x082032b3 in mysql_lock_tables ()
#5  0x082553a7 in lock_tables ()
#6  0x08257970 in open_and_lock_tables ()
#7  0x082890bb in mysql_insert ()
#8  0x08218c77 in mysql_execute_command ()
#9  0x08220089 in mysql_parse ()
#10 0x08220595 in dispatch_command ()
#11 0x08221997 in do_command ()
#12 0x082111ef in handle_one_connection ()
#13 0x00a3c2db in start_thread () from /lib/libpthread.so.0
#14 0x0099614e in clone () from /lib/libc.so.6
Thread 12 (Thread -1588388976 (LWP 25324)):
#0  0x00892402 in __kernel_vsyscall ()
#1  0x00a40146 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#2  0x08326456 in query_cache_end_of_result ()
#3  0x08220091 in mysql_parse ()
#4  0x08220595 in dispatch_command ()
#5  0x08221997 in do_command ()
#6  0x082111ef in handle_one_connection ()
#7  0x00a3c2db in start_thread () from /lib/libpthread.so.0
#8  0x0099614e in clone () from /lib/libc.so.6
Thread 11 (Thread -1588589680 (LWP 25325)):

3. my.cnf
[client]
port            = 3306
socket          = /tmp/mysql.sock

[mysqld]
port            = 3306
socket          = /tmp/mysql.sock
skip-locking
key_buffer = 256M
max_allowed_packet = 1M
table_cache = 256
sort_buffer_size = 1M
read_buffer_size = 1M
read_rnd_buffer_size = 4M
myisam_sort_buffer_size = 64M
thread_cache_size = 8
query_cache_size= 16M
thread_concurrency = 8
max_connections=100
max_connect_errors=100
log-bin=mysql-bin
server-id       = 1
master-host     =   172.16.131.40
master-user     =   monty
master-password =   monty
log-bin=/opt2/sqldemo1/mysql-bin
innodb_data_home_dir = /opt/mysql/data
innodb_data_file_path = ibdata1:10M:autoextend
innodb_log_group_home_dir = /opt/mysql/data
innodb_buffer_pool_size = 256M
innodb_additional_mem_pool_size = 20M
innodb_log_file_size = 64M
innodb_log_buffer_size = 8M
innodb_flush_log_at_trx_commit = 1
innodb_lock_wait_timeout = 50

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash

[isamchk]
key_buffer = 128M
read_buffer = 2M
write_buffer = 2M

[myisamchk]
key_buffer = 128M
sort_buffer_size = 128M
read_buffer = 2M
write_buffer = 2M

[mysqlhotcopy]
interactive-timeout

How to repeat:
Running mysqlslap with engine=MEMORY or engine=MyISAM *and* concurrency set to a value >1 (tried) causes mysqld to hang.

1. Command used for mysqlslap
mysqlslap  --concurrency=1,10,20 --iterations=10 --number-int-cols=2 --number-char-cols=3 --auto-generate-sql --engine=MEMORY --auto-generate-sql-add-autoincrement --auto-generate-sql-load-type=mixed  --number-of-queries=5000 --user=monty --password=monty

The point at which this happens is variable but dependent on --number-of-queries. If this is set to 1000, concurrency=1,25,50,100 also works, but with this set to to 5000/10000, problem happens with even lower concurrency. concurrency=1 always works.
[5 Mar 2008 13:58] Chandrashekhar Marathe
System cpuinfo and meminfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 15
model           : 4
model name      : Intel(R) Pentium(R) D CPU 2.80GHz
stepping        : 7
cpu MHz         : 2797.490
cache size      : 1024 KB
physical id     : 0
siblings        : 2
core id         : 0
cpu cores       : 2
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 5
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm constant_tsc pni monitor ds_cpl cid cx16 xtpr lahf_lm
bogomips        : 5597.45

processor       : 1
vendor_id       : GenuineIntel
cpu family      : 15
model           : 4
model name      : Intel(R) Pentium(R) D CPU 2.80GHz
stepping        : 7
cpu MHz         : 2797.490
cache size      : 1024 KB
physical id     : 0
siblings        : 2
core id         : 1
cpu cores       : 2
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 5
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm constant_tsc pni monitor ds_cpl cid cx16 xtpr lahf_lm
bogomips        : 5593.70

MemTotal:      1024788 kB
MemFree:        468408 kB
Buffers:         11812 kB
Cached:         420524 kB
SwapCached:          0 kB
Active:         302264 kB
Inactive:       218500 kB
HighTotal:      120380 kB
HighFree:          560 kB
LowTotal:       904408 kB
LowFree:        467848 kB
SwapTotal:     4192924 kB
SwapFree:      4192760 kB
Dirty:              72 kB
Writeback:           0 kB
AnonPages:       88488 kB
Mapped:          15724 kB
Slab:            25560 kB
PageTables:       1892 kB
NFS_Unstable:        0 kB
Bounce:              0 kB
CommitLimit:   4705316 kB
Committed_AS:   776512 kB
VmallocTotal:   114680 kB
VmallocUsed:      5692 kB
VmallocChunk:   108852 kB
HugePages_Total:     0
HugePages_Free:      0
HugePages_Rsvd:      0
Hugepagesize:     4096 kB
[5 Mar 2008 20:14] Sveta Smirnova
Thank you for the report.

But version 5.1.22 is a bit old. Could you  please try with current version 5.1.23  and if problem still exists provide your server error log file.
[6 Mar 2008 6:12] Chandrashekhar Marathe
With query cache disabled, the problem did not repeat for following runs:

mysqlslap  --concurrency=1,25,50,100 --iterations=10 --number-int-cols=2 --number-char-cols=3 --auto-generate-sql --engine=MEMORY --auto-generate-sql-add-autoincrement --auto-generate-sql-load-type=mixed  --number-of-queries=10000 --user=monty --password=monty --csv=test.csv

mysqlslap  --concurrency=1,25,50,100 --iterations=10 --number-int-cols=2 --number-char-cols=3 --auto-generate-sql --engine=MyISAM --auto-generate-sql-add-autoincrement --auto-generate-sql-load-type=mixed  --number-of-queries=10000 --user=monty --password=monty --csv=test.csv
[13 Mar 2008 8:57] Chandrashekhar Marathe
With mysql-5.1.23a-maria-alpha, this problem is not observed
[13 Mar 2008 21:33] Sveta Smirnova
Thank you for the feedback.

Closed as "Can't repeat" because last comment.