1

There is a Laravel app with a test suite that runs completely in about 3 minutes.

Somewhere around 2 minutes the test freezes for ~60094ms. Every time it is a different test so it does not seem to be related to any specific test.

None of the tests are failing, they're just experiencing this weird delay. What could be causing 60 seconds delay in PhpUnit?

You should really fix these slow tests (>200ms)...
 1. 60094ms to run Tests\Feature\Superadmin\BusinessActivityTest:testDestroyBusinessActivityProductionProcess
 2. 3357ms to run Tests\Feature\AccessTokenTest:testOauthToken
 3. 1124ms to run Tests\Feature\Superadmin\ArticleTest:testUpdateArticleForAdmin
 4. 969ms to run Tests\Feature\VtaDocumentTest:testUploadVehiclesFileHappyPathWithFilePDF
 5. 737ms to run Tests\Feature\VtaDocumentTest:testUploadCertificateFilePDF
...and there are 22 more above your threshold hidden from view
Time: 2.46 minutes, Memory: 144.25MB

OS phpunit version phpunit -v PHPUnit 7.3.0 by Sebastian Bergmann and contributors. Runtime: PHP 7.3.5-1+ubuntu18.04.1+deb.sury.org+1 with Xdebug 2.7.1

Issue is also there with vendor/bin/phpunit --version PHPUnit 7.5.2 by Sebastian Bergmann and contributors.

<?xml version="1.0" encoding="UTF-8"?>
<phpunit backupGlobals="false"
         backupStaticAttributes="false"
         bootstrap="vendor/autoload.php"
         colors="true"
         convertErrorsToExceptions="true"
         convertNoticesToExceptions="true"
         convertWarningsToExceptions="true"
         processIsolation="false"
         stopOnFailure="false">
    <testsuites>
        <testsuite name="Feature">
            <directory suffix="Test.php">./tests/Feature</directory>
        </testsuite>

        <testsuite name="Unit">
            <directory suffix="Test.php">./tests/Unit</directory>
        </testsuite>
    </testsuites>
    <filter>
        <whitelist processUncoveredFilesFromWhitelist="true">
            <directory suffix=".php">./app</directory>
        </whitelist>
    </filter>
    <php>
        <env name="APP_ENV" value="testing"/>
        <env name="DB_DATABASE" value="testing"/>
        <env name="BCRYPT_ROUNDS" value="4"/>
        <env name="CACHE_DRIVER" value="array"/>
        <env name="SESSION_DRIVER" value="array"/>
        <env name="QUEUE_DRIVER" value="sync"/>
        <env name="MAIL_DRIVER" value="array"/>
    </php>
    <listeners>
        <listener class="JohnKary\PHPUnit\Listener\SpeedTrapListener">
            <arguments>
                <array>
                    <element key="slowThreshold">
                        <integer>200</integer>
                    </element>
                    <element key="reportLength">
                        <integer>5</integer>
                    </element>
                </array>
            </arguments>
        </listener>
    </listeners>
</phpunit>
Margus Pala
  • 8,433
  • 8
  • 42
  • 52
  • Is there any code you could link to? Or am I just really confused about what you're asking here? – FeaturedSpace May 30 '19 at 17:55
  • Added sample test results. Every run the 60000+ millisecond test is different. The test takes long is timewise in more or less same location. – Margus Pala May 31 '19 at 06:27
  • Which Phpunit version iare you using and are there any additional extensions you make use of for the Phpuni ttest-suite? – hakre Jun 02 '19 at 14:11
  • Added phpunit version and configurations. Removing SpeedTrapListener does not avoid the 60s wait. – Margus Pala Jun 02 '19 at 17:02
  • Have you tried opening/tailing your test.log to see if you can find any useful information there? – Dirk Scholten Jun 03 '19 at 12:49
  • Do you have tests that depend on other tests? Do you have mocks in the tests? I've seen nearly endless loops in mock verification on test shutdowns which could cause such long runnings, but the issue is rather obscure (and in my case was reproducible with a Phpunit 6 version for a specifc test-case). Also what I see in the XML configuration there is dfatabases and what not. Network is known to create timing issues (like timeouts, dns resolutions not working etc. pp.) which can create similar events. But hard to say based on the XML only (60... looks like a one minute timeout). – hakre Jun 03 '19 at 19:32
  • I would like to see if anything would change by 1) turn off xdebug 2) make the machine that runs phpunit offline (turn off wifi etc.) making sure there's no external API dependency. – Nobu Jun 05 '19 at 00:05

1 Answers1

1

Turning off the internet avoided the issue.

After debugging and getting stack traces of stuck process with the help of Print PHP Call Stack found out that threads were stuck in MixPanel code.

[New LWP 2893]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f04c2136bf9 in poll () from /lib/x86_64-linux-gnu/libc.so.6
{main}@/usr/local/bin/phpunit:0
main@/usr/local/bin/phpunit:594
run@phar:///usr/local/bin/phpunit/phpunit/TextUI/Command.php:159
doRun@phar:///usr/local/bin/phpunit/phpunit/TextUI/Command.php:203
run@phar:///usr/local/bin/phpunit/phpunit/TextUI/TestRunner.php:587
run@phar:///usr/local/bin/phpunit/phpunit/Framework/TestSuite.php:750
run@phar:///usr/local/bin/phpunit/phpunit/Framework/TestSuite.php:750
run@phar:///usr/local/bin/phpunit/phpunit/Framework/TestSuite.php:750
run@phar:///usr/local/bin/phpunit/phpunit/Framework/TestCase.php:798
runBare@phar:///usr/local/bin/phpunit/phpunit/Framework/TestResult.php:665
tearDown@phar:///usr/local/bin/phpunit/phpunit/Framework/TestCase.php:887
flush@/app/vendor/laravel/framework/src/Illuminate/Foundation/Testing/TestCase.php:142
flush@/app/vendor/laravel/framework/src/Illuminate/Foundation/Application.php:1152
__destruct@/app/vendor/laravel/framework/src/Illuminate/Container/Container.php:1174
flush@/app/vendor/mixpanel/mixpanel-php/lib/Producers/MixpanelBaseProducer.php:96
_persist@/app/vendor/mixpanel/mixpanel-php/lib/Producers/MixpanelBaseProducer.php:117
persist@/app/vendor/mixpanel/mixpanel-php/lib/Producers/MixpanelBaseProducer.php:217
_write@/app/vendor/mixpanel/mixpanel-php/lib/ConsumerStrategies/SocketConsumer.php:122
fwrite@/app/vendor/mixpanel/mixpanel-php/lib/ConsumerStrategies/SocketConsumer.php:210

Furthermore the event of creating new user in MixPanel caused the event to be sent.

enter image description here

Now test is properly decoupled from MixPanel and no more sudden delays.

Margus Pala
  • 8,433
  • 8
  • 42
  • 52