phpunit-speedtrap icon indicating copy to clipboard operation
phpunit-speedtrap copied to clipboard

First test always report a lot of time

Open pablorsk opened this issue 5 years ago • 5 comments

First test report allways like a slowly test

For example

class GeneralTest extends IlluminateTestCase
{
    public function testCool(): void
    {
        $this->assertTrue(true);
    }

    public function testNotCool(): void
    {
        usleep(300000);
        $this->assertTrue(true);
    }
}

You should really fix these slow tests (>80ms)...

  1. 489ms to run Tests\GeneralTest:testCool
  2. 312ms to run Tests\GeneralTest:testNotCool

Any ideas? testCool() has only a simple assert :/

I'm using v3.0.0

pablorsk avatar Jan 29 '19 00:01 pablorsk

Hi @pablorsk, That's frustrating! Let's see what we can find out.

Your helpful issue report shows IlluminateTestCase. Sounds like that's from Laravel and their Illuminate database package. Could you link me to the source code in Laravel codebase that defines this class? I couldn't find it when searching and maybe you have it aliased locally as use ... as IlluminateTestCase

Since Illuminate is a database library, it's very possible Laravel is doing some bootstrapping operations or database creation/hydration before the first case is run. Especially if that code is in IlluminateTestCase::setUp() method. Do you have any ideas what code is running before the test case?

My suggestion is to increase the slowness threshold of the first test case, and possibly other test cases that depend on database interaction:

class GeneralTest extends IlluminateTestCase
{
    /**
     * @slowThreshold 1000
     */
    public function testCool(): void
    {
        $this->assertTrue(true);
    }

    /**
     * @slowThreshold 1000
     */
    public function testNotCool(): void
    {
        usleep(300000);
        $this->assertTrue(true);
    }
}

The above code allows for each test case to run for 1000ms before being considered slow. That might give enough time for the database to do its thing.

johnkary avatar Feb 07 '19 05:02 johnkary

You are right, setUp() function take a some time and this time is added to first test time.

I don't know if is possible on future separate time from setUp and first test, preventing an incorrect information about time of the first test.

This issue, maybe, reports a small bug on library.

pablorsk avatar Feb 16 '19 18:02 pablorsk

Perhaps not related, but a tip nonetheless:

Make sure you don't run migrations/seeds for each test, or even at the start of your test suite. Use https://github.com/drfraker/snipe-migrations to migrate/seed your database, and use transactions whenever you can.

torkiljohnsen avatar Mar 05 '19 10:03 torkiljohnsen

I don't know if is possible on future separate time from setUp and first test, preventing an incorrect information about time of the first test.

setUp() method execution is part of the test run because it executes to begin each test case. It is part of the test execution and should be considered for slowness threshold by default.

I would be open to accepting a PR for a boolean config flag that decides whether to include setUp() in slowness threshold. I don't have any ideas how to make that happen right now. Maybe each test would need report back to the test suite timer to begin timing, or track execution time up until setUp() method is finished.

If you come up with a solution please submit a PR!

The base PHPUnit test class PHPUnit\Framework\TestCase offers a method to override public static function setUpBeforeClass(). Perhaps your database seeding or bootstrapping could be placed here and it not be counted towards slowness?

This issue, maybe, reports a small bug on library.

I do not think this is a bug with the library, but perhaps the README could clarify what test code is measured for being slow. A new section like, "Which PHPUnit test methods are considered part of each test execution?" Investigate which methods from PHPUnit\Framework\TestCase are included, such as setUp(), tearDown(), run(), etc. If you find out please PR against the README!

Do you still think this is a bug? If so, what action should be taken?

johnkary avatar Jun 28 '19 22:06 johnkary

It seems like the added time for the first test is mostly taken by Laravel to boot the application instance, but for future tests it's already cached so that extra time is not spent.

So, what I did was use phpunit bootstrap script pre-instantiate the app instance. This runs before any of the tests are started. It seems to work most :) of the time.

Example phpunit.xml:

<?xml version="1.0" encoding="UTF-8"?>
<phpunit xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:noNamespaceSchemaLocation="./vendor/phpunit/phpunit/phpunit.xsd"
         bootstrap="tests/bootstrap.php"
         colors="true"
>

...

Example tests/bootstrap.php:

<?php

require 'vendor/autoload.php';

$app = require 'bootstrap/app.php';

// prewarm the cache (so our tests aren't counted as slow)
$app->make(Illuminate\Contracts\Console\Kernel::class)->bootstrap();

tam5 avatar Sep 14 '21 17:09 tam5