php – PHPUnit print tests execution time-ThrowExceptions

Exception or error:

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

How to solve:

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

Answer:

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: http://edorian.github.io/2011-01-19-creating-your-custom-phpunit-output.formats/ for the xslt stuff.

Answer:

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:

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:

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:

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:

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:

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.

Answer:

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

$ phpunit –log-json testExport.json

Answer:

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.

Leave a Reply

Your email address will not be published. Required fields are marked *