Salesforce CLI test run ends really slow / takes really long

[rohledermarc]

Summary

We are using the latest Salesforce CLI to run our test suites in our CI on our sandboxes and production environment. We are running each test suite one by one. For each run we use the CLI command sf apex run test --json --target-org **** --suite-names Test_Suite1 --wait 10 --output-dir test-results/apex --result-format json. Apparently the whole run is taking really long, but if we run all tests by just running sf apex run test --wait 10 it is really quick.

It seems like the tests are ready really fast and the json result is shown, but it has kind of a delay till the command ends and the script gets the exit status of the command.

All ~2000 tests through 24 test suites one by one take around 50 minutes (summarised test execution time around 8 minutes), all ~2000 tests at once take around 7 minutes (test execution time around 8 minutes).

Steps To Reproduce

Our repositories of our packages are private, so we can not share it. To reproduce the behaviour it should be enough to:

1. create a lot of tests within 24 test suites
2. run the test suites one by one and write down the time it took (use the script which I add at the bottom of this issue for )
3. run the tests at once and write down the time it took (using sf apex run test --wait 10)
   --> compare the times

Alternative (easier):

1. run sf apex test run and observe how long the command takes to finish and the terminal to be ready again

Expected result

The two compared times should be quite similar and not differ that much.

Actual result

The two compared times differ really much.

System Information

I am using a mac with zsh, but the issue is the same on windows and in our CI, which is using linux.

Salesforce CLI version:

{
  "cliVersion": "@salesforce/cli/2.8.11",
  "architecture": "darwin-arm64",
  "nodeVersion": "node-v20.5.1",
  "osVersion": "Darwin 22.6.0",
  "shell": "zsh",
  "rootPath": "/opt/homebrew/lib/node_modules/@salesforce/cli",
  "pluginVersions": [
    "@oclif/plugin-autocomplete 2.3.8 (core)",
    "@oclif/plugin-commands 2.2.25 (core)",
    "@oclif/plugin-help 5.2.19 (core)",
    "@oclif/plugin-not-found 2.4.1 (core)",
    "@oclif/plugin-plugins 3.4.2 (core)",
    "@oclif/plugin-search 0.0.22 (core)",
    "@oclif/plugin-update 3.2.3 (core)",
    "@oclif/plugin-version 1.3.10 (core)",
    "@oclif/plugin-warn-if-update-available 2.1.0 (core)",
    "@oclif/plugin-which 2.2.32 (core)",
    "@salesforce/cli 2.8.11 (core)",
    "apex 2.3.14 (core)",
    "auth 2.8.16 (core)",
    "data 2.5.8 (core)",
    "deploy-retrieve 1.17.8 (core)",
    "dev 0.7.1 (user)",
    "info 2.6.40 (core)",
    "limits 2.3.33 (core)",
    "login 1.2.29 (core)",
    "marketplace 0.1.3 (core)",
    "org 2.10.6 (core)",
    "packaging 1.17.0 (user)",
    "schema 2.3.25 (core)",
    "settings 1.4.28 (core)",
    "sobject 0.2.6 (core)",
    "source 2.10.33 (core)",
    "telemetry 2.3.1 (core)",
    "templates 55.5.11 (core)",
    "trust 2.6.9 (core)",
    "user 2.3.32 (core)",
    "@tmh-bis-salesforce/tmh-bis-salesforce-cli-plugin 0.5.3 (user)"
  ]
}

Additional information

script for running all tests at once:

#! /bin/bash

username=org_username # set the org username or alias 

echo "Start $(date)"
echo ""

mkdir test-results-once-json

echo "sf apex run test --json --target-org $username --wait 15 --output-dir test-results/apex --result-format json"
sf apex run test --json --target-org $username --wait 15 --output-dir test-results/apex --result-format json > test-results-once-json/test-result.json

echo ""
echo "End $(date)"

result of running the script:

Start Tue Sep 19 12:55:57 CEST 2023

mkdir: test-results-once-json: File exists
sf apex run test --json --target-org *** --wait 15 --output-dir test-results/apex --result-format json

End Tue Sep 19 13:02:03 CEST 2023

script for running the test suites one by one:

#! /bin/bash

username=org_username # set the org username or alias 
testsuites=( TestSuite1 TestSuite2 TestSuite3 TestSuite4 TestSuite5 ... ) # fill in the test suite names

echo "Start $(date)"
echo ""

echo "The following test suites will be executed:"
for value in "${testsuites[@]}"
do
  echo "$value"
done

mkdir test-results-json
for value in "${testsuites[@]}"
do
  echo ""
  echo "sf apex run test --json --target-org $username --suite-names $value --wait 15 --output-dir test-results/apex --result-format json"
  sf apex run test --json --target-org $username --suite-names $value --wait 15 --output-dir test-results/apex --result-format json > test-results-json/$value.json
done

echo ""
echo "End $(date)"

result of running the script

Start Tue Sep 19 11:11:54 CEST 2023

The following test suites will be executed:
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***
***

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

sf apex run test --json --target-org *** --suite-names *** --wait 15 --output-dir test-results/apex --result-format json

End Tue Sep 19 12:02:40 CEST 2023

[github-actions]

Thank you for filing this issue. We appreciate your feedback and will review the issue as soon as possible. Remember, however, that GitHub isn't a mechanism for receiving support under any agreement or SLA. If you require immediate assistance, contact Salesforce Customer Support.

[mshanemc]

Tests, using testSuites, are run asynchronous. So if you have 24 suites run in 50 minutes, that's about 2 min/each.

My theory is that each test suite you enqueue is subject to whatever else is going on the in the queue (deploys, retrieves, dashboards, scheduled apex/flow, etc). So it doesn't take that long to actually run, but it might spend a minute waiting in line. And that can vary depending on what type of load the instance is on.

The test runner is using the streaming API, so it's not like it's polling every 30 seconds or something that could be shortened.

I'm going to close this because I don't think there's a bug, and I'm 100% sure it's not related to the CLI.

[rohledermarc]

@mshanemc thank you for the quick answer. It does not seem like it takes so long because it needs to be enqueued. As I am running the tests, I see really quickly the test results, but the command does not finish / exit. This is the time which leads then to the big delay when running so many test suites. If you are interested and not able to reproduce it, I can try to record a video showing the time period which I mean.

[j-schreiber]

I'm going to close this because I don't think there's a bug, and I'm 100% sure it's not related to the CLI.

I am 100% sure it is related to the CLI. The tests are enqueued in seconds, and usually complete within a couple of seconds. Yet, the CLI needs minutes until it gives back control to the terminal. This used to be different with the old sfdx bundle.

Please consider reopening this issue. I would be available to help you reproduce it and confirm, that it is indeed a CLI problem.

[mshanemc]

OK, hit us with a video of this, and preferably the debug logs that show what's happening.

[j-schreiber]

Just made a short video to demonstrate. I was not able to generate meaningful debug logs (because the tests itself are not the problem, Apex Debug logs of the test execution are useless).

Here's a YouTube link of me demonstrating and trying to explain a little bit. Hope it is helpful: https://youtu.be/GyWwiyZ5TJs

Also, some corrections:

• On CircleCI we use an ubuntu image (not just docker ...)
• The delay is consistent on every environment (personal scratch orgs, CI scratch orgs, sandboxes, production). I am confident that it is not related to other things that may delay the execution of tests.
• It took almost 120 seconds for this run to release terminal after test completion (not only 30-60 seconds, as I guessed)
• In the end you can see that the terminal is available again (but I am not further commenting on that)
• I am demonstrating this with @salesforce/cli/2.7.0 darwin-x64 node-v18.15.0 but we have been observing this behaviour for months now.
• We are seeing this across every machine (mostly Mac's, but also some Windows) of every developer
• When I use the "inline action" in the test class ("Run All tests"), I cannot reproduce this. The tests execute quickly and the results are updated immediately.

If you need more information, please show me how I can provide them.

[iowillhoit]

Thanks for the video @j-schreiber, I am going to try to replicate this today and tomorrow and see if we can find out why this is hanging

[iowillhoit]

Hey @j-schreiber and @rohledermarc, I am not able to reproduce this. I created a simple script that will generate a lot of tests. I then ran sf apex run test and watched the progress with sf apex tail log and in the org UI. As soon as the results were displayed I was given control of my terminal back.

Here is a trimmed video of running 6011 tests on ~2000 files
https://github.com/forcedotcom/cli/assets/1715111/4a275153-e4b1-4c9c-9561-c6e4786a05cc

Are you able to reproduce this issue using my repo? See readme for instructions. https://github.com/iowillhoit/dreamhouse-lots-o-tests

If you can, then something is off with your setup. If you cannot, we are going to need you to create a repo that consistently reproduces this issue for us to debug further. Thank you

[iowillhoit]

FWIW: @mshanemc reminded me of this issue that had a similar issue "hanging" on certain Node versions. I did test using version 20.5.1 and saw the same (quick) results I shared above.

EDIT: Whoops, the link I included was to this same issue. I meant to add #2092