Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: I believe it would also be helpful to allow the mysqlnd debug setting to be used on a non-debug PHP build as well. Previous Comments: [2011-01-22 04:28:47] kriscr...@php.net Sorry for not keeping these comments up-to-date. I've had my head buried triaging this for the last two months now. Anyway, there's a few things to cover. First, I was able to get your mysqlnd debug to work. However, because you have it outputting the debug to a file on each and every PHP run, this filesystem stress is creating a major bottleneck, bringing PHP's perf understress down from around 50 tps (transactions per second) to about 1 or 2 tps. As a result, I am unable to repro this crash with this enabled as you specified in your comment. I would recommend that you perhaps find a way to store this data as an object or whatever and only output to a file in the event of a crash or other error. In any case, I spent some time backtracing this and I believe what we're dealing with is a classic double-free and/or corruption. I have no explanation as to what's causing the corruption to begin with though. I also investigated whether or not this is a threading issue. Contrary to what common sense would suggest, this does not appear to be the case, either. I ran the stress test again on Apache with the -X option (Debug mode), which forces httpd.exe to run as a single process. The crash still occured. No relevant change in the repro. I have also confirmed that this bug is still present in the latest release of 5.3.5. Finally, given the difficulty in reproducing this bug, not to mention the general difficulty in tracking down memory corruption issues in ANSI C in general, I'm now trying a bandaid approach. I added an ifcheck to _zend_mm_free_int in zend_alloc.c at the spot of the top of the crash stack, forcing it to skip the free attempt if the variable in question (next_block) is NULL. I then added some exception handling (using setjmp.h) code to mysqli_result_free_storage in mysqli.c at a spot earlier in the stack, forcing it to throw a PHP warning error (which is set to output to a log file) if there's an exception. I've never tried this in ANSI C before but I think I've got it right. The test is running now and may take awhile to yield a result. I will post a patch early next week. If successful, this won't fix whatever the underlying cause of the corruption is, but it will at least throw an error and spare us a crash, which will allow me to start generating PHP perf results under stress conditions along with the standard perf data. I'll post again when I have the results of this latest test run. [2010-12-02 11:26:33] paj...@php.net You need a debug build to get it working. [2010-12-02 08:45:42] kriscr...@php.net Unfortunately, still no go with the forward slashes. Has this new debug feature actually been tested yet, or perhaps it needs to be enabled in the source then rebuilt? I'm fresh out of ideas. :/ [2010-12-01 23:25:47] kriscr...@php.net Alrighty, I'll try using forward slashes and will post the outcome when it's done. The bug typically takes anywhere from 1 hour up to around 4 hours to repro under stress, so stand by for now. =) [2010-12-01 14:13:55] paj...@php.net Right, but only for the ini setting tests, as it should not be enabled by default :) The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: Sorry for not keeping these comments up-to-date. I've had my head buried triaging this for the last two months now. Anyway, there's a few things to cover. First, I was able to get your mysqlnd debug to work. However, because you have it outputting the debug to a file on each and every PHP run, this filesystem stress is creating a major bottleneck, bringing PHP's perf understress down from around 50 tps (transactions per second) to about 1 or 2 tps. As a result, I am unable to repro this crash with this enabled as you specified in your comment. I would recommend that you perhaps find a way to store this data as an object or whatever and only output to a file in the event of a crash or other error. In any case, I spent some time backtracing this and I believe what we're dealing with is a classic double-free and/or corruption. I have no explanation as to what's causing the corruption to begin with though. I also investigated whether or not this is a threading issue. Contrary to what common sense would suggest, this does not appear to be the case, either. I ran the stress test again on Apache with the -X option (Debug mode), which forces httpd.exe to run as a single process. The crash still occured. No relevant change in the repro. I have also confirmed that this bug is still present in the latest release of 5.3.5. Finally, given the difficulty in reproducing this bug, not to mention the general difficulty in tracking down memory corruption issues in ANSI C in general, I'm now trying a bandaid approach. I added an ifcheck to _zend_mm_free_int in zend_alloc.c at the spot of the top of the crash stack, forcing it to skip the free attempt if the variable in question (next_block) is NULL. I then added some exception handling (using setjmp.h) code to mysqli_result_free_storage in mysqli.c at a spot earlier in the stack, forcing it to throw a PHP warning error (which is set to output to a log file) if there's an exception. I've never tried this in ANSI C before but I think I've got it right. The test is running now and may take awhile to yield a result. I will post a patch early next week. If successful, this won't fix whatever the underlying cause of the corruption is, but it will at least throw an error and spare us a crash, which will allow me to start generating PHP perf results under stress conditions along with the standard perf data. I'll post again when I have the results of this latest test run. Previous Comments: [2010-12-02 11:26:33] paj...@php.net You need a debug build to get it working. [2010-12-02 08:45:42] kriscr...@php.net Unfortunately, still no go with the forward slashes. Has this new debug feature actually been tested yet, or perhaps it needs to be enabled in the source then rebuilt? I'm fresh out of ideas. :/ [2010-12-01 23:25:47] kriscr...@php.net Alrighty, I'll try using forward slashes and will post the outcome when it's done. The bug typically takes anywhere from 1 hour up to around 4 hours to repro under stress, so stand by for now. =) [2010-12-01 14:13:55] paj...@php.net Right, but only for the ini setting tests, as it should not be enabled by default :) [2010-12-01 14:10:34] and...@php.net Pierre, I'm a fan of this, but it can, and will probably, hit the run-time performance. But I can't tell without a benchmark. Unfortunately Ulf has some other things to do at the moment. It is easy to change that, just edit mysqlnd.h and find MYSQLND_DBG_ENABLED and set it to 1 in all cases. The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: Unfortunately, still no go with the forward slashes. Has this new debug feature actually been tested yet, or perhaps it needs to be enabled in the source then rebuilt? I'm fresh out of ideas. :/ Previous Comments: [2010-12-01 23:25:47] kriscr...@php.net Alrighty, I'll try using forward slashes and will post the outcome when it's done. The bug typically takes anywhere from 1 hour up to around 4 hours to repro under stress, so stand by for now. =) [2010-12-01 14:13:55] paj...@php.net Right, but only for the ini setting tests, as it should not be enabled by default :) [2010-12-01 14:10:34] and...@php.net Pierre, I'm a fan of this, but it can, and will probably, hit the run-time performance. But I can't tell without a benchmark. Unfortunately Ulf has some other things to do at the moment. It is easy to change that, just edit mysqlnd.h and find MYSQLND_DBG_ENABLED and set it to 1 in all cases. [2010-12-01 14:06:17] paj...@php.net Wondering if it could be useful to have the logs in non debug builds as well, what do you think? [2010-12-01 11:18:30] and...@php.net Hi, I recently fixed the argument parser for the debug log for Windows, because ":" is a separator in the string. Also only since few weeks the trace log is available on Windows. You need a pretty fresh build sources. Also you need a _debug_ build, because the trace functionality is not compiled in in release builds. And please try using / instead of \, if that helps. The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: Alrighty, I'll try using forward slashes and will post the outcome when it's done. The bug typically takes anywhere from 1 hour up to around 4 hours to repro under stress, so stand by for now. =) Previous Comments: [2010-12-01 14:13:55] paj...@php.net Right, but only for the ini setting tests, as it should not be enabled by default :) [2010-12-01 14:10:34] and...@php.net Pierre, I'm a fan of this, but it can, and will probably, hit the run-time performance. But I can't tell without a benchmark. Unfortunately Ulf has some other things to do at the moment. It is easy to change that, just edit mysqlnd.h and find MYSQLND_DBG_ENABLED and set it to 1 in all cases. [2010-12-01 14:06:17] paj...@php.net Wondering if it could be useful to have the logs in non debug builds as well, what do you think? [2010-12-01 11:18:30] and...@php.net Hi, I recently fixed the argument parser for the debug log for Windows, because ":" is a separator in the string. Also only since few weeks the trace log is available on Windows. You need a pretty fresh build sources. Also you need a _debug_ build, because the trace functionality is not compiled in in release builds. And please try using / instead of \, if that helps. [2010-12-01 10:49:22] kriscr...@php.net Oh and also, could you tell me when this debug is supposed to output the file? I.e. does it output debug info whenever MySQL is invoked, or only when there's a crash? The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: Oh and also, could you tell me when this debug is supposed to output the file? I.e. does it output debug info whenever MySQL is invoked, or only when there's a crash? Previous Comments: [2010-12-01 10:39:51] kriscr...@php.net Hi Ulf, I've been running the tests for Pierre and am also the one who first discovered this bug. He asked me to connect with you here because I've been unable to get the debug directive you mentioned to output. Specifically, I'm running the PHP 5.3.4RC1 ZTS Pierre released, VC9 compile, on Apache 2.2 under one of our Windows 2008 R2 hosts with Windbg attached to the process. In php.ini, I added the following line to the MYSQLND section: mysqlnd.debug="d:t:O,C:\temp\mysqlnd_debug.log" The setting does show up in PHPInfo(). Specifically: mysqlnd mysqlnd enabled Version mysqlnd 5.0.7-dev - 091210 - $Revision: 304625 $ Compression supported SSL not supported Command buffer size 4096 Read buffer size32768 Read timeout31536000 Collecting statistics Yes Collecting memory statisticsYes Tracing d:t:O,C:\temp\mysqlnd_debug.log However, the mysqlnd_debug.log file is never created. I'm not sure under what conditions it's supposed to output, but in this test I was hitting both MediaWiki and WordPress until the crash occured, and at no point was the file created. The directory has full perms (including write) granted to all users. I could theoretically use procmon to see if it's attempting to write the file, but since we're dealing with a bug that takes about an hour to repro, that wouldn't be my first choice. Have you had a chance yet to test this new debug feature? Do you know if there are any other settings/etc that need to be enabled in order for this to work? Please let me know and I'll give it another go. Thanks! --Kris [2010-11-30 12:26:20] paj...@php.net I will ask to enable it and run again the tests. Thanks :) [2010-11-30 12:24:45] u...@php.net Hi Pierre, can you provide a mysqlnd debug log, do you have access to the php.ini? In 5.3.4 mysqlnd learned to write proper debug logs on Windows. Try running PHP with mysqlnd.debug="d:t:O,C:\mysqlnd_debug.log". You need 5.3.4. 5.3.3 won't do it. Thanks, Ulf [2010-11-29 14:12:14] paj...@php.net Yes, it happens as well with current SVN (5.3.4RC1 too). [2010-11-29 14:11:19] paj...@php.net As I said it is not possible yet to get an isolated case. I would have done it already if yes. However, anyone able to do a post mortem analysis could see where and maybe why the crash occurs. memory dumb available if you have such developer (or someone willing to try, not too hard :). The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
Bug #53333 [Com]: Random crash
Edit report at http://bugs.php.net/bug.php?id=5&edit=1 ID: 5 Comment by: kriscr...@php.net Reported by:paj...@php.net Summary:Random crash Status: Feedback Type: Bug Package:MySQLi related Operating System: * PHP Version:5.3.3 Assigned To:mysql Block user comment: N Private report: N New Comment: Hi Ulf, I've been running the tests for Pierre and am also the one who first discovered this bug. He asked me to connect with you here because I've been unable to get the debug directive you mentioned to output. Specifically, I'm running the PHP 5.3.4RC1 ZTS Pierre released, VC9 compile, on Apache 2.2 under one of our Windows 2008 R2 hosts with Windbg attached to the process. In php.ini, I added the following line to the MYSQLND section: mysqlnd.debug="d:t:O,C:\temp\mysqlnd_debug.log" The setting does show up in PHPInfo(). Specifically: mysqlnd mysqlnd enabled Version mysqlnd 5.0.7-dev - 091210 - $Revision: 304625 $ Compression supported SSL not supported Command buffer size 4096 Read buffer size32768 Read timeout31536000 Collecting statistics Yes Collecting memory statisticsYes Tracing d:t:O,C:\temp\mysqlnd_debug.log However, the mysqlnd_debug.log file is never created. I'm not sure under what conditions it's supposed to output, but in this test I was hitting both MediaWiki and WordPress until the crash occured, and at no point was the file created. The directory has full perms (including write) granted to all users. I could theoretically use procmon to see if it's attempting to write the file, but since we're dealing with a bug that takes about an hour to repro, that wouldn't be my first choice. Have you had a chance yet to test this new debug feature? Do you know if there are any other settings/etc that need to be enabled in order for this to work? Please let me know and I'll give it another go. Thanks! --Kris Previous Comments: [2010-11-30 12:26:20] paj...@php.net I will ask to enable it and run again the tests. Thanks :) [2010-11-30 12:24:45] u...@php.net Hi Pierre, can you provide a mysqlnd debug log, do you have access to the php.ini? In 5.3.4 mysqlnd learned to write proper debug logs on Windows. Try running PHP with mysqlnd.debug="d:t:O,C:\mysqlnd_debug.log". You need 5.3.4. 5.3.3 won't do it. Thanks, Ulf [2010-11-29 14:12:14] paj...@php.net Yes, it happens as well with current SVN (5.3.4RC1 too). [2010-11-29 14:11:19] paj...@php.net As I said it is not possible yet to get an isolated case. I would have done it already if yes. However, anyone able to do a post mortem analysis could see where and maybe why the crash occurs. memory dumb available if you have such developer (or someone willing to try, not too hard :). [2010-11-29 14:09:13] u...@php.net Pierre, of course, we'd love to see an isolated phpt test case. As you state, it is not necessarily a mysqli issue but may have some other cause. I agree that Andrey should look at the back trace. Can this reproduced with 5.3.4? If so, please check if you can give us a mysqlnd debug log. It is going to be *very* long. As a first step, please provide us with no more than the last 1000 lines from that log. 1000 lines is a a bit of a random pick to limit the expected long debug log. In 5.3.4 mysqlnd learned to write proper debug logs on Windows. Try running PHP with mysqlnd.debug="d:t:O,C:\mysqlnd_debug.log". You need 5.3.4. 5.3.3 won't do it. Andrey, can you have a look at the backtrace? Thanks, Ulf The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/bug.php?id=5 -- Edit this bug report at http://bugs.php.net/bug.php?id=5&edit=1
