Problem/Motivation

As part of the panoply distribution, the features module has been updated to 7.x-2.6-rc1. After the update, i get a PHP Fatal error when reverting all features via drush fra -y. If I roll back to 7.x-2.5, the issue disappears. The error shows up on my production server only with drush 7.0.0 and PHP 5.3.10 and 256 MB memory limit. Currently i have about 20 custom features installed.

I'm not able to reproduce this error on my local machine with php 5.6.7

Allowed memory size of 268435456 bytes exhausted (tried to allocate 523800 bytes) in /var/www/vhosts/XXXXXX/httpdocs/profiles/XXXXX/modules/contrib/features/features.export.inc on line 1033

Proposed resolution

Remaining tasks

Comments

mpotter’s picture

I could not reproduce this on either my Panopoly instance nor my Open Atrium instance which has more features enabled. Are you using a plain version of Panopoly or do you also have custom features of your own? It might be that one of your custom features is too large.

The recent Features moved some stuff from variables into cache to actually *decrease* memory use. Are you running anything like Memcache to help with this?

Might also just try to boost your memory limit in PHP.ini. Features has always been memory intensive and I typically recommend a setting of 384 MB on development systems that make heavy use of features.

dsnopek’s picture

Looking at the diff between 2.5 and 2.6-rc1 doesn't show any red flags as far as additional memory use.

There was one commit that's doing stuff with static caches that I don't understand, so it might be worth trying with that patch reverted and see if that fixes the problem: #1988252: Use the same language consistently in generated comments and strings

However, I wouldn't be suprised if that doesn't help - just because it's using static caches and I don't personally understand what's going on, doesn't mean it's doing anything wrong. :-)

A couple other ideas:

  1. Try lowering your memory limit with Features 2.5 to see how close to the edge you were. If your memory usage was just below 256Mb with Features 2.5, then pretty much any change could push you over the edge. So, try lowering your memory limit to 200Mb, for example, and do drush fra with Features 2.5 and see if you're hitting the limit. If you do, you can try increasing that and see exactly how close you were to the edge.
  2. Don't limit memory when using PHP from the command line. On my system, I have two seperate php.ini's for running PHP on the web and running PHP on the command-line. For the web, a limit is obviously a good idea! But I don't have a limit on memory when running PHP from the command-line, because that's just me running drush. That might be something to consider!
  3. Try to 'git bisect' your way to the problematic commit. So, if you weren't on the edge of the 256Mb limit previously, and you don't want to remove the memory limit for PHP from the command line, then we'll need to find what change is causing the problem. Looking at the diff doesn't reveal any obvious culprits so narrowing it down to the commit would help. You can try each commit between Features 2.5 and 2.6-rc1, but using 'git bisect' will get you there faster because it uses a binary search to tell you which commit to try next. Please take a look at the documentation in the Git book: https://git-scm.com/book/en/v2/Git-Tools-Debugging-with-Git#Binary-Search

Sorry we don't have an answer for you yet! Hopefully, with a couple experiments we can narrow the problem down. :-)

micbar’s picture

Thank you both mpotter and dsnopek for your quick and thorough answers. I will try 1) and 2) if i find the time. Could be a few weeks until I can share any new findings. For the moment I keep it on 7.x-2.5 because i need a working script for my site deployments.
I suggest to leave this issue active and see if somebody else faces the same problem.

mpotter’s picture

You might also want to try the patch in #2497139: Alter hooks causing overrides due to object properties not sorted to see if that solves the problem.

mpotter’s picture

Status: Active » Postponed (maintainer needs more info)
kenorb’s picture

The same here:

PHP Fatal error: Allowed memory size of 1074741824 bytes exhausted (tried to allocate 134 bytes) in sites/all/modules/contrib/rules/includes/rules.core.inc on line 2206

This happens on: drush fra -y

The problem is that the limit is already set to 1G, but it needs even more (2G?). OPCache and memcached is already in place.

There is around 86 features in total, but I assume only 10-20 of them are in Overridden state.

Not sure what's the possible solution.
I haven't checked the code, but it seems unlikely that one module could causing it, so maybe some memory should be unset/freed between consecutive module reverts?

kenorb’s picture

Status: Postponed (maintainer needs more info) » Active

Happened again:

$ time drush -y fra
Drush bootstrap completed in 15s [Mem: 65 of 1024 MB]
PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 1265555 bytes) in /vagrant/build/docroot/sites/all/modules/contrib/features/features.export.inc on line 1100
real	1m55.481s

It also crashes when I'm trying to list all my features, so I'm not able to give you exact number, but it could be less than 100.

$ time drush fl | grep -i Enabled
Drush bootstrap completed in 11s [Mem: 65 of 1024 MB]                                                                                                                                      [ok]
PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 32 bytes) in /vagrant/build/docroot/sites/all/modules/contrib/features/features.export.inc on line 1118

Allocation of 1G to just load all the features is a huge resource. Especially when I'm doing that within VM which has some already allocated 2G of RAM, so I won't be able to increase it further more.

Note that I'm already using memcached and OPCache for CLI, with XDebug extension disabled including Devel module disabled, so the consumption should be not so large.

It seems line 1100 tried to allocate 1M:

  if (is_array($o) || is_object($o)) {
    $re = '#(r|R):([0-9]+);#';
    $serialize = serialize($o); // <-- LINE 1100

Function: features_remove_recursion() which is part of features_sanitize().

So it sound like something should be optimized.

kenorb’s picture

Some improvements were done in #2543306: drush_features_list() slow - about 220 seconds, but still some operation on large objects are probably not efficient enough.

Maybe we can free up some memory between each feature or use cache to store some data?

kenorb’s picture

This is the test which I did using the following patch and my custom timer functions:

--- a/features.drush.inc
+++ b/features.drush.inc
@@ -216,10 +216,13 @@ function drush_features_list() {
 
   // Sort the Features list before compiling the output.
   $features = features_get_features(NULL, TRUE);
+  _drush_policy_show_time('page');
   ksort($features);
+  _drush_policy_show_time('page');
 
   $rows = array();
   foreach ($features as $k => $m) {
+    _drush_policy_set_time($m->name);
     switch (features_get_storage($m->name)) {
       case FEATURES_DEFAULT:
       case FEATURES_REBUILDABLE:
@@ -244,6 +247,7 @@ function drush_features_list() {
         'state' => $storage
       );
     }
+    _drush_policy_show_time($m->name);
   }
   return $rows;
 }

The above checking for memory_get_usage memory usage.

Here is the result of running drush feature-list:

$ time drush fl
Drush bootstrap completed in 10s [Mem: 65 of 1024 MB]                                                
Drush operation 'page' completed in 23s. [Mem: 82 of 1024 MB]                                        
Drush operation 'page' completed in 23s. [Mem: 82 of 1024 MB]                                        
Drush operation 'accountxeatures' completed in 1s. [Mem: 125 of 1024 MB]                            
Drush operation 'appoinmentxeatures' completed in 0s. [Mem: 125 of 1024 MB]                         
Drush operation 'befxestxfooent' completed in 0s. [Mem: 125 of 1024 MB]                            
Drush operation 'exast' completed in 0s. [Mem: 125 of 1024 MB]                               
Drush operation 'customxreadcrumbsxeaturesxest' completed in 0s. [Mem: 125 of 1024 MB]            
Drush operation 'datexigratexxample' completed in 0s. [Mem: 125 of 1024 MB]                        
Drush operation 'xookingxest_form' completed in 0s. [Mem: 125 of 1024 MB]            
Drush operation 'apealxxarkingxine_form' completed in 0s. [Mem: 125 of 1024 MB]          
Drush operation 'aplyaxulturalxrant_form' completed in 0s. [Mem: 125 of 1024 MB]     
Drush operation 'aplyaxportingxlubxrant_form' completed in 0s. [Mem: 125 of 1024 MB]
Drush operation 'aplyanxllotment_form' completed in 0s. [Mem: 125 of 1024 MB]         
Drush operation 'aplynewxign_form' completed in 0s. [Mem: 125 of 1024 MB]             
Drush operation 'aplyxoxnstallxempxraffic_form' completed in 0s. [Mem: 125 of 1024 MB]  
Drush operation 'paxxarkingxine_form' completed in 0s. [Mem: 125 of 1024 MB]             
Drush operation 'reortxxoodxafetyxoncern_form' completed in 0s. [Mem: 125 of 1024 MB]   
Drush operation 'reortxxrafficxightxssue_form' completed in 0s. [Mem: 125 of 1024 MB]   
Drush operation 'reuestxxulkyxastexollectio_form' completed in 0s. [Mem: 125 of 1024 MB]
Drush operation 'reuestxxarxarkxeasonxicke_form' completed in 0s. [Mem: 125 of 1024 MB]
... 50 more ...
Drush operation 'ppyxoadxlosure_form' completed in 0s. [Mem: 254 of 1024 MB]              
Drush operation 'ppyxkipxermit_form' completed in 0s. [Mem: 254 of 1024 MB]               
Drush operation 'ppyxtreetxollectionxicence_form' completed in 0s. [Mem: 254 of 1024 MB] 
Drush operation 'ppyxtreetxartiesxermission_form' completed in 1s. [Mem: 256 of 1024 MB] 
Drush operation 'enfits' completed in 0s. [Mem: 256 of 1024 MB]                             
Drush operation 'enfitsxhangexfxircumstances_form' completed in 1s. [Mem: 256 of 1024 MB]
Drush operation 'lokxettings' completed in 0s. [Mem: 256 of 1024 MB]                       
Drush operation 'redcrumbs' completed in 0s. [Mem: 257 of 1024 MB]                          
Drush operation 'arinalityxest_form' completed in 0s. [Mem: 257 of 1024 MB]                
Drush operation 'aterinexest_form_form' completed in 0s. [Mem: 257 of 1024 MB]             
Drush operation 'exuncilxaxxfooactxs_form' completed in 1s. [Mem: 257 of 1024 MB]       
Drush operation 'hagexoodxremisesxpproval_form' completed in 1s. [Mem: 260 of 1024 MB]   
Drush operation 'hagexfxirxusxate_form' completed in 0s. [Mem: 260 of 1024 MB]          
Drush operation 'hagexfxircxiscountsxxemp_form' completed in 0s. [Mem: 260 of 1024 MB]  
Drush operation 'omerce' completed in 2s. [Mem: 298 of 1024 MB]                             
Drush operation 'omercexroducts' completed in 1s. [Mem: 299 of 1024 MB]                    
Drush operation 'omercialxastexollection_form' completed in 0s. [Mem: 299 of 1024 MB]     
Drush operation 'omarexumbersxest_form' completed in 0s. [Mem: 299 of 1024 MB]            
Drush operation 'onactxs_form' completed in 0s. [Mem: 299 of 1024 MB]                      
... 50 more ...
Drush operation 'enwxxcaffoldingxndxoarding_form' completed in 0s. [Mem: 423 of 1024 MB]
Drush operation 'enwxcaffoldingxicence_form' completed in 0s. [Mem: 424 of 1024 MB]       
Drush operation 'enwxtreetxorksxicence_form' completed in 1s. [Mem: 424 of 1024 MB]      
Drush operation 'eppedestrianxrossingxroblem_form' completed in 0s. [Mem: 424 of 1024 MB] 
Drush operation 'eprtxxangerousxuilding_form' completed in 0s. [Mem: 424 of 1024 MB]     
Drush operation 'eprtxxeadxnimal_form' completed in 0s. [Mem: 424 of 1024 MB]            
Drush operation 'eprtxxrainagexssue_form' completed in 1s. [Mem: 425 of 1024 MB]         
Drush operation 'eprtxxairxradingxssue_form' completed in 0s. [Mem: 425 of 1024 MB]     
Drush operation 'eprtxxaultyxarxarkxachine_form' completed in 0s. [Mem: 425 of 1024 MB]
Drush operation 'eprtxxatexrime_form' completed in 1s. [Mem: 426 of 1024 MB]             
... 50 more ...
Drush operation 'eqestxnxlleyxate_form' completed in 0s. [Mem: 442 of 1024 MB]           
Drush operation 'eqestxssistedxinxollection_form' completed in 0s. [Mem: 442 of 1024 MB] 
Drush operation 'eqestxulkyxastexollection_form' completed in 0s. [Mem: 442 of 1024 MB]  
Drush operation 'eqestxardenxastexollection_form' completed in 0s. [Mem: 442 of 1024 MB] 
Drush operation 'eqestxnterventionxnxedges_form' completed in 0s. [Mem: 442 of 1024 MB]  
Drush operation 'eqestxestxfoorol_form' completed in 0s. [Mem: 442 of 1024 MB]            
Drush operation 'eqestxestxfoorolxervices_form' completed in 0s. [Mem: 442 of 1024 MB]   
Drush operation 'eqestxradingxtandardsxdvice_form' completed in 0s. [Mem: 442 of 1024 MB]
Drush operation 'oaxrxtreetxignxssue_form' completed in 1s. [Mem: 443 of 1024 MB]       
Drush operation 'ptanimalxelfarexoncern_form' completed in 0s. [Mem: 443 of 1024 MB]      
PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 8208 bytes) in

Fatal error: Allowed memory size of 1073741824 bytes exhausted (tried to allocate 8208 bytes) in /vagrant

real  1m20.908s

Most of the features consist single entityform_type and several field_group and field_instance entries associated with the form.

I just wondering if that memory needs to increase each time.

Secondly there is a big gap of 0.5G and it's caused by the next checked feature consisting 750 rules. This maybe related to where Rules #2702107: Rules are not reverted using Features. or Features #2701957: Rules deployment breaks, due to overridden rules not recognized could have a broken logic when sanitizing invalid data.

This is after setting entity_rebuild_on_flush variable to FALSE (#2698509: Feature revert of hundreds rules takes hours to complete.).

--

Update: It seems rule feature (750 rules) takes 787 MB in memory + 208 form feature modules takes 443 MB, which gives 1.2GB usage in total.

$ drush ev "module_load_include('inc', 'features', 'features.export'); var_dump(features_get_storage('my_rules'));"
Drush operation 'ev module_load_include('inc', 'features', 'features.export'); var_dump(features_get_storage('my_rules'));' completed in 0s. [Mem: 787 of 1024 MB]

So it seems the features_get_storage() function takes almost 1GB in memory only to return single 0 value?

--

Update: I did additional test by actually increasing it to 2GB, and it seems the memory wasn't dropped when rule feature was parsed, e.g.

Starting 'my_road_issue_form', time: 0s. [Mem: 442 of 2024 MB]                     
Drush operation 'my_road_issue_form' completed in 1s. [Mem: 443 of 2024 MB]        
Starting 'my_rpt_animal_form', time: 0s. [Mem: 443 of 2024 MB]                    
Drush operation 'my_rpt_animal_form' completed in 0s. [Mem: 443 of 2024 MB]       
Starting 'my_rules', time: 0s. [Mem: 443 of 2024 MB]                                              
Drush operation 'my_rules' completed in 19s. [Mem: 1067 of 2024 MB]                               
Starting 'my_rules_engine_test_custom_benefit_form', time: 0s. [Mem: 1067 of 2024 MB]             
Drush operation 'my_rules_engine_test_custom_benefit_form' completed in 0s. [Mem: 1067 of 2024 MB]
Starting 'my_rules_test_form', time: 0s. [Mem: 1067 of 2024 MB]                                   
Drush operation 'my_rules_test_form' completed in 0s. [Mem: 1067 of 2024 MB]                      
Starting 'my_school_transport_form', time: 0s. [Mem: 1067 of 2024 MB]                      
Drush operation 'my_school_transport_form' completed in 0s. [Mem: 1067 of 2024 MB]         
Starting 'my_services', time: 0s. [Mem: 1067 of 2024 MB]                                          
Drush operation 'my_services' completed in 0s. [Mem: 1072 of 2024 MB]                             

Could it be PHP bug, since it's not freeing up the memory on time? And actually we can't unset anything in here. I've tried calling gc_collect_cycles() between the storage calls, but it didn't help either.

I've tested above with PHP 5.5.33, in PHP 5.6.20 it seems it's consuming less memory for some reason (354 instead of 787, after I recompiled PHP and added some xdebug, debug symbols, pear, etc. it's 612 - still less).