| 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: | |
| Category: | MySQL Server | Severity: | S2 (Serious) |
| Version: | 5.1.22-rc | OS: | Linux (RHEL5) |
| Assigned to: | CPU Architecture: | Any | |
[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.
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.