PHPUnit print tests execution time

Question

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

score 21 · Answer 1 · edited Feb 22 '22 at 00:07

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.

My listener extends `PHPUnit_Framework_BaseTestListener`, and I found `$test->time()` wouldn't work for elapsed time. However, based on a comment elsewhere on this page, `$test->getTestResultObject()->time()` works fine. `$time` is good for per-test time, too. — halfer, Mar 22 '15 at 21:33
The first two links are dead. Could you update them and/or post some example code for adding it to the XML file? — marcovtwout, Oct 15 '15 at 14:08
https://phpunit.de/manual/current/en/appendixes.configuration.html#appendixes.configuration.test-listeners — marcovtwout, Oct 15 '15 at 14:16

score 21 · Answer 2 · answered Jul 21 '11 at 11:45

21

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.

answered Jul 21 '11 at 11:45

jkulak

768
1
6
18

can't find a reader for this file. the first line show – user1077915 Jul 07 '23 at 17:55

score 9 · Answer 3 · answered Jan 26 '14 at 12:59

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"

Not possible in PHPUnit 6, as `--log-json` option was removed. — Cranio, Dec 18 '18 at 06:32

score 7 · Answer 4 · edited May 23 '17 at 12:18

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>

score 4 · Answer 5 · answered Oct 20 '15 at 14:25

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.

I had to add a file property, `` – Dennis Jul 06 '16 at 15:07 — Dennis, Jul 06 '16 at 15:07

score 4 · Accepted Answer · edited Jun 26 '12 at 21:05

4

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

edited Jun 26 '12 at 21:05

Kevin Burke

61,194
76
188
305

answered Mar 04 '11 at 17:15

tobyS

860
1
7
15

1

I was hoping there was a more "automatic" way to do that but i think that this is the best alternative – mck89 Mar 04 '11 at 17:26
Data you ask for is being collected during test execution - you just need to save it to a file with an extra option - see my answer. – jkulak Feb 06 '17 at 13:35

score 3 · Answer 7 · answered Mar 04 '11 at 17:06

3

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.

answered Mar 04 '11 at 17:06

Pascal MARTIN

395,085
80
655
663

6

It does this for you automatically. There's no need to re-do it each time. It's stored in the PHPUnit_Framework_TestResult instance for each test. Simply call `$result->time();` to get the time spent... – ircmaxell Mar 04 '11 at 17:28
Oh ; I learnt something, here, again :-) Thanks for the comment ! – Pascal MARTIN Mar 04 '11 at 17:31
`Call to undefined method MyTest::time()` :( – Jürgen Paul Aug 09 '13 at 08:24
2

`$this->getTestResultObject()->time()`? – PeerBr Oct 08 '14 at 17:00
How do you get the test method name from tearDown()? – bancer Nov 14 '15 at 18:47

score 3 · Answer 8 · edited Mar 22 '15 at 21:22

3

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...

edited Mar 22 '15 at 21:22

halfer

19,824
17
99
186

answered Mar 04 '11 at 17:23

ircmaxell

163,128
34
264
314

score 1 · Answer 9 · answered Sep 11 '17 at 13:00

1

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

$ phpunit --log-json testExport.json

answered Sep 11 '17 at 13:00

Adam Nader

11
2

1

`--log-json` was deprecated and removed in PHPUnit 6. – Cranio Dec 18 '18 at 06:33

score 0 · Answer 10 · answered Jan 26 '15 at 16:22

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.

PHPUnit print tests execution time

10 Answers10

Linked