PHPUnit print tests execution time

Question

is there a way to print the execution time of each test with PHPUnit?

Answer 1

You can implement your own test runner, for example by extending PHPUnit_TextUI_TestRunner and make it collect and print run times.

Answer 2

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>

Answer 3

In my opinion, the simplest solution is to export test statistic as json:

$ phpunit --log-json testExport.json

Answer 4

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 &lt;boolean:false&gt; 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.

Answer 5

I guess you could use the setUp and tearDown methods (which are called at the beginning and end of each test, respectively) to :

• Log the current time before the test, in setUp,
• And calculate the time the test took, in tearDown.

Of course, you'll have to do this in each one of your test classes -- or in a super-class which will be inherited by all your test classes.

Answer 6

Well, you can have it export the execution time with Logging. It's not directly outputted as the result, but you could write a pretty report viewer that would output the results of the log file (either from JSON or XML). That should get you what you want...

Answer 7

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"

Answer 8

I liked @adri's answer. It got me started on this:

alias phpunittime=" | awk '\$NF ~ '/,/' && \$1 ~ /\"(test|time)\"/' \
    | cut -d: -f2- \
    | sed \"N;s/\n/--/\"  \
    | sed \"s/,//\"   \
    | awk 'BEGIN{FS=\"--\"}; {print \$2 \$1}' | sort -r \
    | head"

To use, you'll need to configure PHP unit to output to a JSON log file. To do so, make your phpunit.xml look like this:

<phpunit>
    <logging>
        <log type="json" target="/tmp/logfile.json"/>
    </logging>
</phpunit>

Then use like this:

$ cat /tmp/logfile.json | phpunittime

To see more or less than 10 timings, say 2 or 19, use -n 2 or -n 19, respectively, at the end.

What's nice about this is it doesn't make assumptions about how you call/run phpunit itself (in my case, I use CakePHP and run my command like this: Console/cake test app). Also, you can run your tests and see their output as normal... your terminal doesn't just sit there until the tests are done.

Answer 9

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.

Answer 10

Here's a complete example based on the idea from edorians answer. Tested on PHPunit 4.

Create the following PHP class:

class ProfilingTestListener extends PHPUnit_Framework_BaseTestListener
{
    public function endTest(PHPUnit_Framework_Test $test, $time)
    {
        printf("Test '%s' ended.\tTotal time %s s.\tTest time %s s.\n",
            str_pad($test->toString(), 50),
            number_format($test->getTestResultObject()->time(), 3),
            number_format($time, 3)
        );
    }
}

Add the following to your phpunit.xml:

<phpunit ..>
    ...
    <listeners>
        <listener class="ProfilingTestListener"></listener>
    </listeners>
    ...
</phpunit>

---

Example output:

PHPUnit 4.7.7 by Sebastian Bergmann and contributors.

Test 'FooTest::testFoo              ' ended.    Total time 2.050 s. Test time 0.026 s. 
.Test 'FooTest::testBar             ' ended.    Total time 2.077 s. Test time 1.000 s.
.Test 'FooTest::testBar2            ' ended.    Total time 3.077 s. Test time 0.730 s.