PHPUnit print tests execution time
Just add --log-junit "my_tests_log.xml" and then open this file with spreadsheet application (Excel, Numbers, Calc) to view it. You get all information you ask for, and you can sort by test execution time.
Many of the current answers discuss how to access and analyze the duration times in the log file. I will share two ways to modify the CLI output in phpUnit version 3.7.38 (which is what Travis-CI uses for PHP by default), building on @edorian's incomplete answer.
Use a custom printer to override the CLI output. I can't find any documentation for printers but they appear to be supported. You can see which methods are available in the source code.
class TestDurationPrinter extends PHPUnit_TextUI_ResultPrinter
{
public function endTest(PHPUnit_Framework_Test $test, $time)
{
printf("Test '%s' ended and took %s seconds.\n",
$test->getName(),
$time
);
}
}
Then add these lines as attributes to phpunit in the phpunit.xml file:
printerFile="path/to/TestDurationPrinter.php"
printerClass="TestDurationPrinter"
You can also use the --printer CLI option but that doesn't play well with namespaces.
You can add to the CLI output, as opposed to overriding it, with a TestListener by implementing the PHPUnit_Framework_TestListener interface (this is the same interface that printers use). This will still print ., S, and F so be sure to account for that, if you desire.
class TestDurationListener implements PHPUnit_Framework_TestListener
{
public function endTest(PHPUnit_Framework_Test $test, $time)
{
printf("Test '%s' ended and took %s seconds.\n",
$test->getName(),
$time
);
}
public function addError(PHPUnit_Framework_Test $test, Exception $e, $time)
{
}
public function addFailure(PHPUnit_Framework_Test $test, PHPUnit_Framework_AssertionFailedError $e, $time)
{
}
public function addIncompleteTest(PHPUnit_Framework_Test $test, Exception $e, $time)
{
}
public function addRiskyTest(PHPUnit_Framework_Test $test, Exception $e, $time)
{
}
public function addSkippedTest(PHPUnit_Framework_Test $test, Exception $e, $time)
{
}
public function startTest(PHPUnit_Framework_Test $test)
{
}
public function startTestSuite(PHPUnit_Framework_TestSuite $suite)
{
}
public function endTestSuite(PHPUnit_Framework_TestSuite $suite)
{
}
}
In version 3.8 and above there is a PHPUnit_Framework_BaseTestListener that can be extended so that you only define the methods you want to override.
class TestDurationListener extends PHPUnit_Framework_BaseTestListener
{
public function endTest(PHPUnit_Framework_Test $test, $time)
{
printf("Test '%s' ended.\n", $test->getName());
}
}
To include your new listener, add these lines to your phpunit.xml file:
<listeners>
<listener class="TestDurationListener" file="path/to/TestDurationListener.php" />
</listeners>
If you don't like to write a Testlistener, like it was suggested already, you can use the following script to parse the PHPUnit's JSON Test Result in an easier to read format:
alias phpunit-report-runtime="phpunit --log-json php://stdout \
| awk '\$NF ~ '/,/' && \$1 ~ /\"(test|time)\"/' \
| cut -d: -f2- \
| sed \"N;s/\n/--/\" \
| sed \"s/,//\" \
| awk 'BEGIN{FS=\"--\"}; {print \$2 \$1}' | sort -r \
| head -n 5"
Format is <time in seconds>, <test method>. Example output:
$ phpunit-report-runtime
0.29307007789612, "VCR\\Util\\SoapClientTest::testDoRequestHookDisabled"
0.16475319862366, "VCR\\CassetteTest::testRecordAndPlaybackRequest"
0.092710018157959, "VCR\\Util\\SoapClientTest::testDoRequest"
0.031861782073975, "VCR\\LibraryHooks\\SoapTest::testShouldInterceptCallWhenEnabled"
0.026772022247314, "VCR\\LibraryHooks\\AbstractFilterTest::testRegisterAlreadyRegistered"
To add some more ways:
You can write a custom Test listener and add it to the XML file. In that listener you can access the $testResult->time(). Some lines in your phpunit.xml and a 10 line PHP class. Not too much hassle.
class SimpleTestListener implements PHPUnit_Framework_TestListener
{
public function endTest(PHPUnit_Framework_Test $test, $time)
{
printf("Test '%s' ended and took %s seconds.\n",
$test->getName(),
$test->time()
);
}
}
If you generate a junit.xml anyways (for CI or while creating code coverage) all the numbers are there anyways and with a simple XSLT you can make those even more readable.
Example junit.xml
<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
<testsuite name="DemoTest" file="/home/edo/foo.php" tests="2" assertions="2" failures="1" errors="0" time="0.007727">
<testcase name="testPass" class="DemoTest" file="/home/edo/foo.php" line="4" assertions="1" time="0.003801"/>
<testcase name="testFail" class="DemoTest" file="/home/edo/foo.php" line="8" assertions="1" time="0.003926">
<failure type="PHPUnit_Framework_ExpectationFailedException">DemoTest::testFail
Failed asserting that <boolean:false> is true.
/home/edo/foo.php:9
</failure>
</testcase>
</testsuite>
</testsuites>
and with an transformation like this:
<?xml version="1.0"?>
<xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform">
<xsl:template match="/">
<html>
<body>
<h1>Tests</h1>
<xsl:for-each select="testsuites/testsuite">
<h2><xsl:value-of select="@name"/></h2>
<ul>
<xsl:for-each select="testcase">
<li>
<xsl:value-of select="@name"/> : <xsl:value-of select="@time"/>
<xsl:if test="failure">
<b>Failed !</b>
<i><xsl:value-of select="*"/></i>
</xsl:if>
</li>
</xsl:for-each>
</ul>
</xsl:for-each>
</body>
</html>
</xsl:template>
</xsl:stylesheet>
you get lines showing you: <li>testPass : 0.003801</li> (the HTML is just an example, it should be easily adaptable).
Referencing my own blog post here: https://edorian.github.io/2011-01-19-creating-your-custom-phpunit-output.formats/ for the xslt stuff.