diff --git a/core/modules/simpletest/lib/Drupal/simpletest/TestBase.php b/core/modules/simpletest/lib/Drupal/simpletest/TestBase.php index d3c3bf9..61c3d2a 100644 --- a/core/modules/simpletest/lib/Drupal/simpletest/TestBase.php +++ b/core/modules/simpletest/lib/Drupal/simpletest/TestBase.php @@ -732,6 +732,25 @@ protected function error($message = '', $group = 'Other', array $caller = NULL) return $this->assert('exception', $message, $group, $caller); } + protected $benchEvents = array(); + + protected function bench($event) { + if (!isset($this->benchEvents[$event])) { + $this->benchEvents[$event] = microtime(TRUE); + } + else { + $start = $this->benchEvents[$event]; + $stop = microtime(TRUE); + unset($this->benchEvents[$event]); + if (PHP_SAPI == 'cli') { + vprintf(" %7s %-30s\n", array( + sprintf('%3.3F', $stop - $start), + $event, + )); + } + } + } + /** * Logs verbose message in a text file. * @@ -839,7 +858,9 @@ public function run(array $methods = array()) { $test_completion_check_id = TestBase::insertAssert($this->testId, $class, FALSE, 'The test did not complete due to a fatal error.', 'Completion check', $caller); try { + $this->bench('prepareEnvironment'); $this->prepareEnvironment(); + $this->bench('prepareEnvironment'); } catch (\Exception $e) { $this->exceptionHandler($e); @@ -854,7 +875,9 @@ public function run(array $methods = array()) { } try { + $this->bench("setUp()"); $this->setUp(); + $this->bench("setUp()"); } catch (\Exception $e) { $this->exceptionHandler($e); @@ -865,13 +888,17 @@ public function run(array $methods = array()) { break; } try { + $this->bench("$method()"); $this->$method(); + $this->bench("$method()"); } catch (\Exception $e) { $this->exceptionHandler($e); } try { + $this->bench("tearDown()"); $this->tearDown(); + $this->bench("tearDown()"); } catch (\Exception $e) { $this->exceptionHandler($e); @@ -883,7 +910,9 @@ public function run(array $methods = array()) { break; } + $this->bench("restoreEnvironment()"); $this->restoreEnvironment(); + $this->bench("restoreEnvironment()"); // Remove the test method completion check record. TestBase::deleteAssert($test_completion_check_id); } diff --git a/core/modules/simpletest/lib/Drupal/simpletest/WebTestBase.php b/core/modules/simpletest/lib/Drupal/simpletest/WebTestBase.php index 7cfbc58..f20f641 100644 --- a/core/modules/simpletest/lib/Drupal/simpletest/WebTestBase.php +++ b/core/modules/simpletest/lib/Drupal/simpletest/WebTestBase.php @@ -51,6 +51,16 @@ protected $curlHandle; /** + * Whether the test performed any HTTP request. + * + * @see \Drupal\simpletest\WebTestBase::curlExec() + * @see \Drupal\simpletest\WebTestBase::tearDown() + * + * @var bool + */ + private $testPerformedRequest = FALSE; + + /** * The headers of the page currently loaded in the internal browser. * * @var Array @@ -888,6 +898,9 @@ protected function setUp() { if (empty($path)) { _current_path('run-tests'); } + + // @see \Drupal\simpletest\WebTestBase::tearDown() + $this->testPerformedRequest = FALSE; } /** @@ -1117,6 +1130,9 @@ protected function refreshVariables() { * created by setUp(), and resets the database prefix. */ protected function tearDown() { + if (!$this->testPerformedRequest) { + $this->fail('This test did not perform a single HTTP request. Use DrupalUnitTestBase instead.'); + } // Destroy the testing kernel. if (isset($this->kernel)) { $this->kernel->shutdown(); @@ -1203,6 +1219,7 @@ protected function curlInitialize() { * @see curlInitialize() */ protected function curlExec($curl_options, $redirect = FALSE) { + $this->testPerformedRequest = TRUE; $this->curlInitialize(); if (!empty($curl_options[CURLOPT_URL])) { @@ -1440,9 +1457,11 @@ protected function drupalGet($path, array $options = array(), array $headers = a // We re-using a CURL connection here. If that connection still has certain // options set, it might change the GET into a POST. Make sure we clear out // previous options. + $this->bench("GET /$path"); $out = $this->curlExec(array(CURLOPT_HTTPGET => TRUE, CURLOPT_URL => $url, CURLOPT_NOBODY => FALSE, CURLOPT_HTTPHEADER => $headers)); // Ensure that any changes to variables in the other thread are picked up. $this->refreshVariables(); + $this->bench("GET /$path"); // Replace original page output with new output from redirected page(s). if ($new = $this->checkForMetaRefresh()) { @@ -1628,10 +1647,12 @@ protected function drupalPostForm($path, $edit, $submit, array $options = array( else { $post = $this->serializePostValues($post) . $extra_post; } + $this->bench("POST /$path"); $out = $this->curlExec(array(CURLOPT_URL => $action, CURLOPT_POST => TRUE, CURLOPT_POSTFIELDS => $post, CURLOPT_HTTPHEADER => $headers)); // Ensure that any changes to variables in the other thread are picked // up. $this->refreshVariables(); + $this->bench("POST /$path"); // Replace original page output with new output from redirected // page(s). @@ -1913,8 +1934,10 @@ protected function drupalProcessAjaxResponse($content, array $ajax_response, arr * @see url() */ protected function drupalPost($path, $accept, array $post, $options = array()) { - return $this->curlExec(array( - CURLOPT_URL => url($path, $options + array('absolute' => TRUE)), + $url = url($path, $options + array('absolute' => TRUE)); + $this->bench("POST /$path"); + $out = $this->curlExec(array( + CURLOPT_URL => $url, CURLOPT_POST => TRUE, CURLOPT_POSTFIELDS => $this->serializePostValues($post), CURLOPT_HTTPHEADER => array( @@ -1922,6 +1945,8 @@ protected function drupalPost($path, $accept, array $post, $options = array()) { 'Content-Type: application/x-www-form-urlencoded', ), )); + $this->bench("POST /$path"); + return $out; } /** @@ -2035,9 +2060,11 @@ protected function checkForMetaRefresh() { protected function drupalHead($path, array $options = array(), array $headers = array()) { $options['absolute'] = TRUE; $url = $this->container->get('url_generator')->generateFromPath($path, $options); + $this->bench("HEAD /$path"); $out = $this->curlExec(array(CURLOPT_NOBODY => TRUE, CURLOPT_URL => $url, CURLOPT_HTTPHEADER => $headers)); // Ensure that any changes to variables in the other thread are picked up. $this->refreshVariables(); + $this->bench("HEAD /$path"); if ($this->dumpHeaders) { $this->verbose('GET request to: ' . $path . diff --git a/core/scripts/run-tests.sh b/core/scripts/run-tests.sh index a953dd7..5a0d9c3 100755 --- a/core/scripts/run-tests.sh +++ b/core/scripts/run-tests.sh @@ -9,6 +9,7 @@ use Drupal\Core\Database\Database; use Drupal\Core\DrupalKernel; use Drupal\Core\Site\Settings; +use Drupal\simpletest\TestBase; use Symfony\Component\HttpFoundation\Request; require_once __DIR__ . '/../vendor/autoload.php'; @@ -72,9 +73,15 @@ simpletest_script_reporter_init(); // Execute tests. +$bench = array(); for ($i = 0; $i < $args['repeat']; $i++) { simpletest_script_execute_batch($test_list); } +echo "\n", 'Most expensive tests:', "\n\n"; +arsort($bench); +foreach ($bench as $class => $time) { + echo sprintf('%13s %s', format_interval($time), $class), "\n"; +} // Stop the timer. simpletest_script_reporter_timer_stop(); @@ -576,6 +583,11 @@ function simpletest_script_execute_batch($test_classes) { global $args, $test_ids; // Multi-process execution. + $descriptors = array( + 0 => array('pipe', 'r'), + 1 => array('pipe', 'w'), + 2 => array('pipe', 'a'), + ); $children = array(); while (!empty($test_classes) || !empty($children)) { while (count($children) < $args['concurrency']) { @@ -597,7 +609,7 @@ function simpletest_script_execute_batch($test_classes) { // Fork a child process. $command = simpletest_script_command($test_id, $test_class); - $process = proc_open($command, array(), $pipes, NULL, NULL, array('bypass_shell' => TRUE)); + $process = proc_open($command, $descriptors, $pipes, NULL, NULL, array('bypass_shell' => TRUE)); if (!is_resource($process)) { echo "Unable to fork test process. Aborting.\n"; @@ -610,6 +622,7 @@ function simpletest_script_execute_batch($test_classes) { 'test_id' => $test_id, 'class' => $test_class, 'pipes' => $pipes, + 'start' => microtime(TRUE), ); } @@ -620,6 +633,14 @@ function simpletest_script_execute_batch($test_classes) { foreach ($children as $cid => $child) { $status = proc_get_status($child['process']); if (empty($status['running'])) { + // Record total time of test class. + $GLOBALS['bench'][$child['class']] = microtime(TRUE) - $child['start']; + + // Print stdout of the subprocess (TestBase::bench() output). + echo 'Bench: ', $child['class'], "\n"; + echo stream_get_contents($child['pipes'][1]); + fclose($child['pipes'][1]); + // The child exited, unregister it. proc_close($child['process']); if ($status['exitcode']) { @@ -696,8 +717,19 @@ function simpletest_script_run_one_test($test_id, $test_class) { $test = new $test_class($test_id); $test->dieOnFail = (bool) $args['die-on-fail']; $test->verbose = (bool) $args['verbose']; + $start = microtime(TRUE); $test->run(); + $duration = microtime(TRUE) - $start; + $max_duration = 3 * 60; + + $message = "Test duration: " . format_interval($duration) . ' (max allowed: ' . format_interval($max_duration) . ').'; + TestBase::insertAssert($test_id, $test_class, $duration <= $max_duration, $message, 'Performance', array( + 'function' => $test_class, + 'line' => 0, + 'file' => 'run-tests.sh', + )); + simpletest_script_reporter_display_summary($test_class, $test->results); // Finished, kill this runner.