| Bug #34043 | Server loops excessively in _checkchunk() when safemalloc is enabled | ||
|---|---|---|---|
| Submitted: | 24 Jan 2008 20:47 | Modified: | 21 Aug 2010 1:25 |
| Reporter: | Philip Stoev | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: General | Severity: | S1 (Critical) |
| Version: | 5.1-BK | OS: | Any |
| Assigned to: | Davi Arnaut | CPU Architecture: | Any |
[24 Jan 2008 20:47]
Philip Stoev
[24 Jan 2008 21:01]
Philip Stoev
Thread stacks for bug #34043 with various levels of verbosity
Attachment: bug34043-stacks.txt (text/plain), 282.34 KiB.
[24 Jan 2008 21:08]
Philip Stoev
The thread appears to be cycling in that region: 515 for (irem= sf_malloc_root; irem != NULL && count-- ; irem= irem->next) 516 flag+= _checkchunk (irem, filename, lineno); Plenty of free memory is available. Error log contains: Warning: found too many locks at write_wait: enter write_lock repeated about a dozen times.
[25 Jan 2008 14:46]
Philip Stoev
I am sorry, but the the core and the datadir were not preserved. Please let me know if they are needed and I will rerun the test case until I get new ones.
[28 Jan 2008 21:07]
Guilhem Bichot
The stack traces mention MERGE code and server (sql/) code, this does not look Maria-specific. Serg also think this does not look Maria-specific. I suggest re-testing with MyISAM instead.
[30 Jan 2008 16:56]
Philip Stoev
This issue is present when using MyISAM against the latest 5.1 BitKeeper treee. The core and the data directory from a previous run are available at: dl360-g5-a:/data1/maria/systest_vardir-bug34043 The directory includes the binary that was used, along with a dump of all threads (bug34043.threads). Here is the thread that is cycling from the latest run: [Switching to thread 31 (Thread 1167137088 (LWP 23396))]#0 0x000000000096c678 in _sanity (filename=0xb4a970 "array.c", lineno=281) at safemalloc.c:490 490 for (irem= sf_malloc_root; irem != NULL && count-- ; irem= irem->next) (gdb) bt #0 0x000000000096c678 in _sanity (filename=0xb4a970 "array.c", lineno=281) at safemalloc.c:490 #1 0x000000000096be7c in _myfree (ptr=0x1d8ee598, filename=0xb4a970 "array.c", lineno=281, myflags=16) at safemalloc.c:264 #2 0x0000000000978de9 in delete_dynamic (array=0x1d9d19a0) at array.c:281 #3 0x00000000007f85f5 in sp_pcontext::destroy (this=0x1d9d1918) at sp_pcontext.cc:129 #4 0x00000000007f56d0 in sp_head::destroy (this=0x1d9d1558) at sp_head.cc:756 #5 0x00000000007f5830 in ~sp_head (this=0x1d9d1558) at sp_head.cc:738 #6 0x0000000000801b22 in ~Table_triggers_list (this=0x1dd3df18) at sql_trigger.cc:978 #7 0x000000000068f877 in intern_close_table (table=0x1caca9d8) at sql_base.cc:852 #8 0x000000000068f924 in free_cache_entry (table=0x1caca9d8) at sql_base.cc:876 #9 0x0000000000977ff9 in hash_delete (hash=0xf58ca0, record=0x1caca9d8 "xЖё\033") at hash.c:529 #10 0x000000000068e6a2 in close_open_tables (thd=0x2aaaac29b388) at sql_base.cc:1254 #11 0x000000000068eab9 in close_thread_tables (thd=0x2aaaac29b388) at sql_base.cc:1398 #12 0x00000000007f11ff in sp_lex_keeper::reset_lex_and_exec_core (this=0x1e2e22f0, thd=0x2aaaac29b388, nextp=0x4590f398, open_tables=false, instr=0x1e2e22b0) at sp_head.cc:2703 #13 0x00000000007f1862 in sp_instr_stmt::execute (this=0x1e2e22b0, thd=0x2aaaac29b388, nextp=0x4590f398) at sp_head.cc:2809 #14 0x00000000007f38e4 in sp_head::execute (this=0x1e2d3698, thd=0x2aaaac29b388) at sp_head.cc:1221 #15 0x00000000007f45d3 in sp_head::execute_procedure (this=0x1e2d3698, thd=0x2aaaac29b388, args=0x2aaaac29d488) at sp_head.cc:1945 #16 0x000000000064c1ff in mysql_execute_command (thd=0x2aaaac29b388) at sql_parse.cc:4090 #17 0x000000000064e27f in mysql_parse (thd=0x2aaaac29b388, inBuf=0x1e1bac08 "CALL ins_tb0_eng1 (@tmp_num, @tmp_word)", length=39, found_semicolon=0x45910f00) at sql_parse.cc:5623 #18 0x000000000064f052 in dispatch_command (command=COM_QUERY, thd=0x2aaaac29b388, packet=0x2aaaac2cc7e9 "CALL ins_tb0_eng1 (@tmp_num, @tmp_word)", packet_length=39) at sql_parse.cc:1121 #19 0x00000000006503ee in do_command (thd=0x2aaaac29b388) at sql_parse.cc:781 #20 0x000000000063e08f in handle_one_connection (arg=0x2aaaac29b388) at sql_connect.cc:1120 #21 0x0000003ba88062f7 in start_thread () from /lib64/libpthread.so.0 #22 0x0000003ba80ce85d in clone () from /lib64/libc.so.6
[30 Jan 2008 20:18]
Konstantin Osipov
Philip, I would greatly appreciate if you reduce the test case to a simple SQL script (possibly mysql-test language script). That would save time to many people (myself, engineer, reviewer). Thanks.
[31 Jan 2008 10:27]
Philip Stoev
Test case for bug #34043
Attachment: bug34043.zip (application/x-zip-compressed, text), 65.31 KiB.
[31 Jan 2008 10:31]
Philip Stoev
It turns out the issue is that mysqld spends all of its time in _checkchunk() (safemalloc is enabled due to a debug build) and thus all tables remain perpetually locked. Only a single CPU core is used, the rest are idle. While the manual does say that safemalloc is very slow, I still think that a completely hanging server is a bug of some sort. How to repeat: 1. Compile a debug binary; 2. Download the attached archive, placing the .txt files in mysql-test and the .test files in mysql-test/t. 3. Run test as follows: perl ./mysql-test-run.pl --stress --stress-init-file=bug_34043_init.txt \ --stress-test-file=bug_34043_run.txt --stress-test-duration=600 \ --stress-threads=200 --mysqld=--max_connections=500 You will observe some initial progress, afterwards the test output will cease. logging into the server, running show processlist or show table status or shutdown will become extremely slow operations. If you run the test with --stress-threads=50, you will observe nice progress all the way.
[31 Jan 2008 17:06]
Sergei Golubchik
Just a couple of thoughts: It's, of course, normal for safemalloc to spend time checking memory links, and depending on the allocation pattern it can waste quite a lot of time doing it. All the effects, described in the bugreport, are, basically, expected, safemalloc using a lot of CPU time in _checkchunk() is certainly not a bug. On the other hand, _checkchunk() would need a lot of time only when there are a lot (and I mean, A LOT - a really huge number) of small memory blocks allocated. This could often mean a problem in a code - for example, mem_root with badly chosen default parameters (too small block size, resulting in a huge number of blocks). This needs to be investigated (mysqladmin debug should help, probably)
[31 Jan 2008 17:16]
Philip Stoev
Whatever it is, the performance hit is pretty severe -- only 1 core is ever used. If it is impossible to remedy this, then we should ship the debug binary with safemalloc disabled, otherwise we will run into trouble with customers who run debug binaries for any reason. I am also concerned that the data structure being walked by _checkchunk() gets corrupt when more than a certain number of threads are accessing it.
[23 Apr 2008 20:05]
Philip Stoev
6.0 is also affected. Can we somehow increase the priority of this. If this situation occurs, complete transaction serialization results -- only a single thread, which holds a lock, loops in _checkchunk() and no other threads are able to move forward.
[1 Jul 2010 15:13]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/112691 3085 Davi Arnaut 2010-07-01 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Essentially, the problem is that safemalloc is excruciatingly slow as it checks all allocated blocks for overrun at each memory management primitive, yielding a almost exponential slowdown for the memory management functions (malloc, realloc, free). The overrun check basically consists of verifying some bytes of a block for certain magic keys, which catches some simple forms of overrun. Another minor problem is violation of aliasing rules and that its own internal list of blocks is prone to corruption. Given the magnitude of memory debuggers available nowadays, especially those that are provided with the platform malloc implementation, maintenance of a in-house and largely obsolete memory debugger becomes a burden that is not worth the effort due to its slowness and lack of support for detecting more common forms of heap corruption. Since there are third-party tools (such as valgrind, malloc debug, etc) that can provide the same functionality at a lower or comparable performance cost, the solution is to simply remove safemalloc. The removal of safemalloc also allows a simplification of the malloc wrappers, removing quite a bit of kludge: redefinition of my_malloc, my_free and the removal of the unused second argument of my_free. Since my_free always check whether the supplied pointer is null, redudant checks are also removed. @ client/mysqldump.c Pass my_free directly as its signature is compatible with the callback type -- which wasn't the case for free_table_ent.
[8 Jul 2010 21:00]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/113178 3102 Davi Arnaut 2010-07-08 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Essentially, the problem is that safemalloc is excruciatingly slow as it checks all allocated blocks for overrun at each memory management primitive, yielding a almost exponential slowdown for the memory management functions (malloc, realloc, free). The overrun check basically consists of verifying some bytes of a block for certain magic keys, which catches some simple forms of overrun. Another minor problem is violation of aliasing rules and that its own internal list of blocks is prone to corruption. Another issue with safemalloc is rather the maintenance cost as the tool has a significant impact on the server code. Given the magnitude of memory debuggers available nowadays, especially those that are provided with the platform malloc implementation, maintenance of a in-house and largely obsolete memory debugger becomes a burden that is not worth the effort due to its slowness and lack of support for detecting more common forms of heap corruption. Since there are third-party tools that can provide the same functionality at a lower or comparable performance cost, the solution is to simply remove safemalloc. Third-party tools can provide the same functionality at a lower or comparable performance cost. The removal of safemalloc also allows a simplification of the malloc wrappers, removing quite a bit of kludge: redefinition of my_malloc, my_free and the removal of the unused second argument of my_free. Since free() always check whether the supplied pointer is null, redudant checks are also removed. Also, this patch adds unit testing for my_malloc and moves my_realloc implementation into the same file as the other memory allocation primitives. @ client/mysqldump.c Pass my_free directly as its signature is compatible with the callback type -- which wasn't the case for free_table_ent.
[8 Jul 2010 21:45]
Davi Arnaut
Queued to mysql-trunk
[8 Jul 2010 21:48]
Davi Arnaut
Alternatives to safemalloc include: * mtrace - catches memory leaks and is very fast * mudflap - catches memory leaks and is a bit slower. * Valgrind * malloc debug A summary of memory debuggers are found here http://en.wikipedia.org/wiki/Memory_debugger http://developer.apple.com/mac/library/documentation/Darwin/Reference/ManPages/man3/malloc... http://developer.apple.com/mac/library/documentation/Darwin/Reference/ManPages/man3/libgma... http://developer.apple.com/mac/library/technotes/tn2004/tn2124.html
[9 Jul 2010 1:20]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/113192 3103 Davi Arnaut 2010-07-08 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Post-merge fix: cast argument and correct type in assignment.
[9 Jul 2010 11:18]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/113230 3105 Davi Arnaut 2010-07-09 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Post-merge fix: remove reference to file that is now gone.
[17 Jul 2010 14:56]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/113812 3127 Davi Arnaut 2010-07-17 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Post-merge fix: remove leftovers from safemalloc removal.
[23 Jul 2010 12:25]
Bugs System
Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (version source revid:vasil.dimov@oracle.com-20100531152341-x2d4hma644icamh1) (merge vers: 5.5.5-m3) (pib:18)
[23 Jul 2010 12:32]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100723121929-90e9zemk3jkr2ocy) (version source revid:vasil.dimov@oracle.com-20100531152341-x2d4hma644icamh1) (pib:18)
[1 Aug 2010 22:36]
Paul DuBois
Noted in 5.5.6 changelog. safemalloc was excessively slow under certain conditions and has been removed.
[2 Aug 2010 0:11]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/114814 3161 Davi Arnaut 2010-08-01 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Post-merge fix: remove --with-debug=full, it was only used for safemalloc.
[9 Aug 2010 13:18]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/115315 3167 Davi Arnaut 2010-08-09 Bug#34043: Server loops excessively in _checkchunk() when safemalloc is enabled Post-merge fix: add missing comma.
[16 Aug 2010 6:29]
Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@sun.com-20100816062701-qo9dpnk5tkt1pksb) (version source revid:alik@sun.com-20100816062603-xc16eftmv7rmktyq) (merge vers: 5.6.1-m4) (pib:20)
[16 Aug 2010 6:37]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100816062819-bluwgdq8q4xysmlg) (version source revid:alik@sun.com-20100816062612-enatdwnv809iw3s9) (pib:20)
[16 Aug 2010 15:29]
Paul DuBois
Noted in 5.6.1 changelog.
