In two separate installations, both D7, "drush upc" checks the status of each module multiple times. As a result, on a small site the command takes twice as long as it should and on a large site basically never stops.

Comments

jonhattan’s picture

jonhattan
Primary language Spanish
Location Plasencia
commented
Priority: Normal » Major

Summary of a debug output

[...]

Load alias @server_master [1.55 sec, 21.83 MB]                                                                       [notice]
Including /usr/src/drush/commands/pm/updatecode.pm.inc [1.56 sec, 21.85 MB]                                       [bootstrap]
Extension deploy is fetched from git. Ignoring. [3.95 sec, 23.74 MB]                                                  [debug]
Extension views is fetched from git. Ignoring. [3.96 sec, 23.77 MB]                                                   [debug]
Extension views_ui is fetched from git. Ignoring. [3.96 sec, 23.77 MB]                                                [debug]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]
batch-process 256 256 --backend=2 2>&1 [5.2 sec, 24.88 MB]
php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default batch-process      [notice]
256 256 --backend=2 2>&1 [5.2 sec, 24.89 MB]

[...]

Load alias @server_master [8.13 sec, 21.66 MB]                                                                       [notice]
Checking available update data ... [8.16 sec, 21.97 MB]                                                           [ok]
Failed to check available update data for ldap. [8.88 sec, 21.98 MB]                                              [ok]
Checked available update data for Media: YouTube. [9.46 sec, 21.98 MB]                                            [ok]
Checked available update data for Panels. [10.28 sec, 21.98 MB]                                                   [ok]
Checked available update data for Block user messages. [11.4 sec, 21.98 MB]                                       [ok]
Failed to check available update data for Node relativity. [12.05 sec, 21.98 MB]                                  [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [12.06 sec, 21.98 MB]            [batch]
Command dispatch complete [12.07 sec, 21.93 MB]                                                                      [notice]
Peak memory usage was 22.98 MB [12.08 sec, 21.93 MB]                                                                 [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [16.21 sec, 21.67 MB]                                                                      [notice]
Checked available update data for Rules. [17.46 sec, 21.99 MB]                                                    [ok]
Checked available update data for Simplenews. [18.11 sec, 21.99 MB]                                               [ok]
Checked available update data for ThemeKey. [19.33 sec, 21.99 MB]                                                 [ok]
Checked available update data for Basic. [20.47 sec, 21.99 MB]                                                    [ok]
Checked available update data for Administration menu. [21.11 sec, 21.99 MB]                                      [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [21.12 sec, 21.99 MB]            [batch]
Command dispatch complete [21.12 sec, 21.94 MB]                                                                      [notice]
Peak memory usage was 22.99 MB [21.13 sec, 21.94 MB]                                                                 [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [25.65 sec, 21.67 MB]                                                                      [notice]
Checked available update data for AWS SDK for PHP. [27.14 sec, 21.99 MB]                                          [ok]
Checked available update data for Block. [28.58 sec, 21.99 MB]                                                    [ok]
Checked available update data for Chaos tools. [29.16 sec, 21.99 MB]                                              [ok]
Checked available update data for Devel. [30.3 sec, 21.99 MB]                                                     [ok]
Checked available update data for Entity API. [31.47 sec, 21.99 MB]                                               [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [31.47 sec, 21.99 MB]            [batch]
Command dispatch complete [31.48 sec, 21.94 MB]                                                                      [notice]
Peak memory usage was 22.99 MB [31.5 sec, 21.94 MB]                                                                  [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [35.15 sec, 21.67 MB]                                                                      [notice]
Checked available update data for File Entity. [35.9 sec, 21.99 MB]                                               [ok]
Checked available update data for Libraries. [36.62 sec, 21.99 MB]                                                [ok]
Checked available update data for Link. [37.28 sec, 21.99 MB]                                                     [ok]
Checked available update data for Media. [38.39 sec, 21.99 MB]                                                    [ok]
Checked available update data for Media Browser Plus. [39.1 sec, 21.99 MB]                                        [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [39.11 sec, 21.99 MB]            [batch]
Command dispatch complete [39.12 sec, 21.94 MB]                                                                      [notice]
Peak memory usage was 22.99 MB [39.12 sec, 21.94 MB]                                                                 [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [41.99 sec, 21.67 MB]                                                                      [notice]
Checked available update data for Pathauto. [42.77 sec, 21.99 MB]                                                 [ok]
Checked available update data for Styles. [43.94 sec, 21.99 MB]                                                   [ok]
Checked available update data for Token. [45.06 sec, 21.99 MB]                                                    [ok]
Checked available update data for Actions permissions. [45.73 sec, 21.99 MB]                                      [ok]
Checked available update data for Admin. [46.32 sec, 21.99 MB]                                                    [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [46.33 sec, 21.99 MB]            [batch]
Command dispatch complete [46.33 sec, 21.94 MB]                                                                      [notice]
Peak memory usage was 22.99 MB [46.34 sec, 21.94 MB]                                                                 [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [49.54 sec, 21.67 MB]                                                                      [notice]
Checked available update data for Calendar. [50.94 sec, 21.99 MB]                                                 [ok]
Checked available update data for CCK. [51.75 sec, 21.99 MB]                                                      [ok]
Checked available update data for Coder. [52.94 sec, 21.99 MB]                                                    [ok]
Checked available update data for Commerce. [54.05 sec, 21.99 MB]                                                 [ok]
Checked available update data for Context. [54.73 sec, 21.99 MB]                                                  [ok]
Batch process has consumed in excess of 50% of available memory. Starting new thread [54.74 sec, 21.99 MB]            [batch]
Command dispatch complete [54.75 sec, 21.94 MB]                                                                      [notice]
Peak memory usage was 22.99 MB [54.77 sec, 21.94 MB]                                                                 [memory]
Backend invoke: php /usr/src/drush/drush.php  --verbose --debug --no --root=/var/www/drupal7 --uri=http://default   [command]

[...]

Load alias @server_master [57.98 sec, 21.67 MB]                                                                      [notice]
Checked available update data for Date. [59.24 sec, 21.99 MB]                                                     [ok]
Checked available update data for Display suite. [60.37 sec, 21.99 MB]                                            [ok]
Checked available update data for Email. [61.01 sec, 21.99 MB]                                                    [ok]
Checked available update data for Features. [62.24 sec, 21.99 MB]                                                 [ok]

[...]

relevant php.ini settings:

max_execution_time = 30
memory_limit = -1
jonhattan’s picture

jonhattan
Primary language Spanish
Location Plasencia
commented
Priority: Major » Normal

Not the best log summary but I did see duplication in a first run. It is on an old site I use for testing. Now after drush cc all & drush pm-refresh I'm unable to see duplicity.

@Damien does it happen to you consistently?

daniorama’s picture

daniorama commented

It happens to me also everytime I try. It does it exactly 5 times consistently.

Dave-B’s picture

Dave-B commented

Workaround: Check available updates via the web interface, then use Drush to run the updates.

jonhattan’s picture

jonhattan
Primary language Spanish
Location Plasencia
commented
Status: Active » Closed (duplicate)

Let's continue in #1352102: pm-update unusable, hangs, loops. It seems there're more clues there.