|
|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[2009-03-19 00:02 UTC] ninzya at inbox dot lv
Description: ------------ My configuration is Windows XP, Apache 2.2.11.0, PHP 5.3.0beta1, i'm coding a framework and periodically i am performing stress tests with apache's ab.exe. Once my framework has become quite processive (lotsa operations involved in request processing), there started to appear unexpected PHP errors/warning in a PHP error log file. For details see reproduce code. Reproduce code: --------------- I was performing periodical stress testing by running "ab.exe -c 30 -n 10000 http://..../myframeworkpage.php". Sometimes PHP error log had been empty after 10000 req. stress testing, sometimes there were some errors/warning (from 1 to 10 usually), and these errors were reporting absurd things happening around. What i noticed, is that under heavy load PHP manages to implicitly reset some variables to NULL value, or "lose value", which results in NULL value. Here are some of those errors and my assumptions for those errors: 1) "PHP Notice: Use of undefined constant - assumed '' in ... on line 25", where line #25 is "$Db->connect( DB_PERS, DB_HOST, DB_PORT, DB_USER, DB_PASS);". This is definately failure of PHP. 2) "PHP Fatal error: Call to a member function fetch() on a non-object in ... on line 611" where line #611 is "while( $this->Db->fetch( $this->query));". Please note that this cycle is contained within __destruct() method (probably $Db property is being destroyed too soon when php execution ends, but i assume it was also implicitly reset to NULL). Definately failure of PHP. 3) "PHP Warning: mysql_pconnect(): Access denied for user 'root'@'localhost' (using password: NO) in ... on line 163" where line #163 is "$link =mysql_pconnect( $host .':' .$port, $user, $pass, $clientFlags);" and $pass was never set to null or whatsoever (it contains string password, always). I could assume here failure of MySQL server. 4) "PHP Warning: mysql_real_escape_string() expects parameter 2 to be resource, null given in ... on line 483" where line #483 is "return '\'' .mysql_real_escape_string( $data, $this->link) .'\'';" and i'm 100% sure $link property is not null at the step, when call to mysql_real_escape_string is issued. I could assume here failure of MySQL server, which resulted in resource to become null (which is also absurd). 5) "PHP Warning: Invalid argument supplied for foreach() in ... on line 414" where line #414 is "foreach( $patchset as $blockId =>$fill)", and $patchset is a reference to an array, always. Definately failure of PHP. And much more such examples, which all say the same thing - "i got the null value, what the hell?". I tried to make some stress testings for such code as: class X { public function __construct() { } public function __destruct() { } public function test() { } public function Y() { return new Y( $this); } } class Y { protected $X; public function __construct( $X) { $this->X =$X; } public function __destruct() { $this->X->test(); } } $X =new X(); $Y =$X->Y(); $C =$X->Y(); $A =$X->Y(); but it executed successfully with no errors. I tried 300000 requests, everything went fine. But, when i stress-test my framework, PHP *sometimes* acts weird. So far i failed to find compact reproduction code for this issue. Expected result: ---------------- I expect to see no warnings described in "Reproduce code" section. Actual result: -------------- PHP under heavy load implicitly resets random variable's value to NULL or "looses" random variable's value, which results in assignment of NULL value to that variable. PatchesPull RequestsHistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||||||||||||
Copyright © 2001-2024 The PHP GroupAll rights reserved. |
Last updated: Sun Dec 22 21:01:29 2024 UTC |
Every mentioned error/warning occurs randomly. It is not possible to trigger these warnings (especially first) during each request, something related to memory fails i think, or stack is being corrupted or something. I was investigating this problem for past day and i found this. Take a look at the following script: <?php function throw_exc() { throw new Exception('TEST_EXCEPTION'); } class Test { public function __construct() { echo 'Constr' ."\n"; } public function __destruct() { echo 'Destr' ."\n"; } } try { $T =new Test( throw_exc()); } catch( Exception $e) { echo 'Exception: ' .$e->getMessage(); } ?> Execution of this script produces: Destr Exception: TEST_EXCEPTION Where it should produce only this part: Exception: TEST_EXCEPTION As you can see, destructor is being called, where it shouldn't be. I will make a temporary work around for this situation and investigate further, because i guess this is not the problem that has caused first warning/error message i mentioned above.I got a little bit closer to the problem. Here's what happens. See this script: // load page $sql ='SELECT id, ' .implode( ', ', $properties) .' FROM ' .TAB_PREF .'pages WHERE node_id =' .$Db->escape( $nodeId, 'UINT').' AND alt_name =' .$Db->escape( $pageAlt, 'STRING') .' LIMIT 0, 1;'; if(( $row =$Db->queryFirst( $sql)) ===null) throw new Exception( 'NOT_FOUND'); if( $row['id'] ===null) {// THIS IS WHERE YOU SHOULD LOOK AT trigger_error( 'Got NULL!', E_USER_WARNING); trigger_error( 'SQL: ' .$sql, E_USER_WARNING); ob_start(); var_dump( $row); trigger_error( ob_get_clean(), E_USER_WARNING); die(); } As you can see, i am testing if $row['id'] is null (this is unexpected situation when this field becomes null, it's an auto column and at this step i expect successfully fetched row), and if it is NULL, then i wish to see the debug info for the contents of $row and overall "what's going on". Now here is the error log when this unexpected situation is being RANDOMLY triggered during stress test: [20-Mar-2009 14:20:37] PHP Warning: Got NULL! in D:\...\pages.php on line 93 [20-Mar-2009 14:20:37] PHP Warning: SQL: SELECT id, `title`, `keywords`, `descr`, `template_id` FROM pages WHERE node_id =11 AND alt_name ='welcome' LIMIT 0, 1; in D:\...\pages.php on line 94 [20-Mar-2009 14:20:37] PHP Warning: array(5) { ["id"]=> string(6) "SHARED" ["title"]=> string(12) "My test page" ["keywords"]=> string(6) "asdasd" ["descr"]=> string(6) "asdasd" ["template_id"]=> string(4) "8567" } in D:\...\pages.php on line 97 I don't know how to explain this. I guess this is mysqlnd failing this bad.Please excuse me for the delay. I have been figuring out what's the cause of this bug and finally i have something to come up with. The problem is in mysql_free_result function. Not in itself, but it's behavior has changed. Consider the following example from the PHP manual on mysql_free_result: Example #1 A mysql_free_result() example <?php $result = mysql_query("SELECT id,email FROM people WHERE id = '42'"); if (!$result) { echo 'Could not run query: ' . mysql_error(); exit; } /* Use the result, assuming we're done with it afterwards */ $row = mysql_fetch_assoc($result); /* Now we free up the result and continue on with our script */ mysql_free_result($result); echo $row['id']; echo $row['email']; ?> This code with PHP 5.3.0 with mysqlnd will now fail under high concurrency, because mysql_free_result will affect $row variable and allow another threads to use it's zval to store data. I suspect that mysql_free_result marks the referenced by $row data as 'free' and another threads pick that zval up and work with it. As soon as you release result, another thread may corrupt $row variable. Test this example under high concurrency and you will get different values for $row['id'] and $row['email']. Run 10000 req. test and some of them will fail to produce correct output. In my framework i use mysql_free_result before referencing last fetched row of result set very often, that's why i hit this bug 'randomly'. I have another example i just tested, this is part of my framework. The idea is the same - mysql_free_result is being called before actually using fetched data array. $con =mysql_pconnect( 'localhost', 'root', ''); mysql_select_db( 'ewe10'); $q =mysql_query( $sql ='SELECT id, title, keywords, descr, template_id, `title`, `keywords`, `descr`, `template_id` FROM pages WHERE node_id =11 AND alt_name =\'welcome\' LIMIT 0, 1;', $con); $row =mysql_fetch_assoc( $q); mysql_free_result( $q); if( $row['id'] ===null || $row['template_id'] !=8567 || $row['title'] !='My test page' || $row['keywords'] !='asdasd' || $row['descr'] !='asdasd') { trigger_error( 'FAIL!', E_USER_WARNING); trigger_error( 'SQL: ' .$sql, E_USER_WARNING); ob_start(); var_dump( $row); trigger_error( ob_get_clean(), E_USER_WARNING); die('NOT OK'); } die('OK'); SQL for the table: CREATE TABLE `ewe10`.`pages` ( `id` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT 'unique page id', `node_id` int(10) unsigned NOT NULL COMMENT 'node id in which this page is', `title` varchar(128) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'page title', `keywords` varchar(128) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'page keywords', `descr` text CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'page description', `template_id` int(10) unsigned DEFAULT NULL COMMENT 'template this page is using (if NULL, template was deleted from database and this page is stored as a backup)', `type` enum('MAIN','PAGE') CHARACTER SET latin1 NOT NULL DEFAULT 'PAGE' COMMENT 'page type', `alt_name` varchar(45) CHARACTER SET latin1 NOT NULL COMMENT 'page alternative name', `date_add` datetime NOT NULL COMMENT 'when page was added', PRIMARY KEY (`id`), UNIQUE KEY `NODE_ID_ALT_NAME` (`node_id`,`alt_name`) USING BTREE, KEY `FK_pages_templates` (`template_id`), KEY `TYPE` (`type`), KEY `FK_pages_map` (`node_id`), KEY `DATE_ADD` (`date_add`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=FIXED; the only row in this table is shown on the screenshot i referenced in previous report. To address the issue more quickly, i would like to give you a hint - after calling mysql_free_result there is no possibility to fetch any more rows, so there's nothing to worry about mysql_fetch_*(), but there is possibility that the last fetched row may be referenced. This means - even if mysql_free_result was called, last fetched row must remain locked in mysqlnd internal zval cache until the variable is implicitly/explicitly unset.Hi, I switched on the zval cache and tried to reproduce the problem, with no success. I tested with Apache2 MPM. `ab` concurrency level starting from 20 up to 100. Time from 30 to 45 seconds. I got, with your code, only 3 types of errors. I added mysql_connect() myself - mysql_connect() fails because cannot have more connections on the unix socket. Using TCP/IP exhausts the resources earlier for connecting to MySQL - mysql_query() tries to connect, although the connection has failed, typical for mysql_query()! It fails : -- password problem -- no resources I did not see any corruption whatsoever. Difference from you is that I tested on Linux, as server. ab was running on a Mac connected over a FastEthernet switch. Here follows the code I used: <?php $conn = mysql_connect("localhost", "root", "root"); mysql_select_db("test"); $result = mysql_query("SELECT a,b FROM stress_test"); if (!$result) { echo 'Could not run query: ' . mysql_error(); exit; } /* Use the result, assuming we're done with it afterwards */ $row = mysql_fetch_assoc($result); /* Now we free up the result and continue on with our script */ mysql_free_result($result); var_dump($row); ?>