`sf apex get test` throws heap out of memory

pawel-id commented 1 month ago

Summary

We have quite big project having currently c.a. 2300+ apex tests. Starting with version @salesforce/cli/2.37.4 we are experiencing heap out memory when triggering those tests via CLI. The tests on the org runs fine, however on the CLI we have:

[152:0x7f2dda78b680] 33404559 ms: Mark-Compact 4019.9 (4131.4) -> 4004.8 (4132.1) MB, 1852.90 / 0.00 ms (average mu = 0.145, current mu = 0.026) allocation failure; scavenge might not succeed
[152:0x7f2dda78b680] 33406649 ms: Mark-Compact 4020.7 (4132.1) -> 4005.4 (4132.9) MB, 2021.94 / 0.00 ms (average mu = 0.090, current mu = 0.033) allocation failure; scavenge might not succeed

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
----- Native stack trace -----
/scripts-1089-2040536/step_script: line 259: 152 Aborted (core dumped) sf apex run test -c -v -r junit -w 480 -l RunLocalTests -d output

It seems that CLI tries to allocate more then 4GB memory and fails.

Affected commands:

sf apex run test -c -v -r junit -w 480 -l RunLocalTests -d output - this is complete command we initially found that problem. It runs the tests for many hours and then do some post-processing and finally fail.
sf apex get test -c -i 707afas... -d output - this is a bit simpler command retrieving existing test run and doing only the post processing. It fails the same way, but it doesn’t require to run tests, but rather gather existing tests and doing some post processing. This is minimal and convenient way to replicate.

Steps to reproduce

Authorize an org. The credentials are provided within Salesforce case #467133949. There are scratch orgs having our project deployed and tests run.
Find existing test run id on the org. It should begin with 707...
Run the command providing proper test run id sf apex get test -c -i 7073O00002aQRQqQAO -c -d output . This usually takes 15-20 min and then it fails with heap out of memory.
The replication on 16GB computer does not require additional settings. However it might be that you will have computer with larger amount of RAM it might be required to limit node memory like this NODE_OPTIONS=--max-old-space-size=4096 (just guessing).

Expected result

Test report saved into output folder.

Actual result

The CLI exists with non zero exit code and heap out of memory as above.

System Information

We replicated this on macOS, Linux and Windows. It seems not OS dependent.

{
  "architecture": "darwin-arm64",
  "cliVersion": "@salesforce/cli/2.39.6",
  "nodeVersion": "node-v20.12.2",
  "osVersion": "Darwin 23.4.0",
  "rootPath": "/Users/pawel/.nvm/versions/node/v20.12.2/lib/node_modules/@salesforce/cli",
  "shell": "bash",
  "pluginVersions": [
    "@oclif/plugin-autocomplete 3.0.16 (core)",
    "@oclif/plugin-commands 3.3.1 (core)",
    "@oclif/plugin-help 6.0.21 (core)",
    "@oclif/plugin-not-found 3.1.6 (core)",
    "@oclif/plugin-plugins 5.0.14 (core)",
    "@oclif/plugin-search 1.0.23 (core)",
    "@oclif/plugin-update 4.2.7 (core)",
    "@oclif/plugin-version 2.0.17 (core)",
    "@oclif/plugin-warn-if-update-available 3.0.15 (core)",
    "@oclif/plugin-which 3.1.8 (core)",
    "@salesforce/cli 2.39.6 (core)",
    "apex 3.1.9 (core)",
    "auth 3.6.3 (core)",
    "community 3.0.20 (user)",
    "data 3.3.2 (core)",
    "deploy-retrieve 3.6.6 (core)",
    "dev 2.1.12 (user)",
    "functions 1.22.11 (user)",
    "info 3.2.3 (core)",
    "limits 3.3.4 (core)",
    "marketplace 1.2.4 (core)",
    "org 4.1.3 (core)",
    "packaging 2.4.0 (core)",
    "schema 3.3.4 (core)",
    "settings 2.2.1 (core)",
    "signups 2.0.20 (user)",
    "sobject 1.3.6 (core)",
    "source 3.3.3 (core)",
    "telemetry 3.3.4 (core)",
    "templates 56.2.4 (core)",
    "trust 3.6.6 (core)",
    "user 3.5.2 (core)",
    "vlocityestools 0.24.8 (user)"
  ]
}

github-actions[bot] commented 1 month ago

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.

pawel-id commented 1 month ago

Here are last few lines of a log. It might be helpful to determine failing operation

{"level":20,"time":1714094822092,"name":"sf:elapsedTime","msg":"CodeCoverage.queryAggregateCodeCov - exit","elapsedTime":1587.355986}
{"level":20,"time":1714094822094,"name":"sf:elapsedTime","msg":"CodeCoverage.getAggregateCodeCoverage - exit","elapsedTime":1590.129882}
{"level":20,"time":1714094822094,"name":"sf:elapsedTime","msg":"CodeCoverage.getOrgWideCoverage - enter"}
{"level":20,"time":1714094822095,"name":"sf:connection","method":"GET","url":"https://napoleon-broth-211.scratch.my.salesforce.com/services/data/v60.0/tooling/query?q=SELECT%20PercentCovered%20FROM%20ApexOrgWideCoverage","headers":{"content-type":"application/json","user-agent":"sfdx toolbelt:"},"msg":"request"}
{"level":20,"time":1714094822260,"name":"sf:elapsedTime","msg":"CodeCoverage.getOrgWideCoverage - exit","elapsedTime":165.877896}
{"level":20,"time":1714094822260,"name":"sf:elapsedTime","msg":"AsyncTests.formatAsyncResults - exit","elapsedTime":1843305.83755}
{"level":20,"time":1714094822260,"name":"sf:elapsedTime","msg":"AsyncTests.runTests - exit","elapsedTime":22977229.298226}
{"level":20,"time":1714094822260,"name":"sf:elapsedTime","msg":"TestService.runTestAsynchronous - exit","elapsedTime":22977229.389393}
{"level":20,"time":1714094822415,"name":"sf:elapsedTime","msg":"JUnitReporter.format - enter"}
{"level":20,"time":1714094822415,"name":"sf:elapsedTime","msg":"JUnitReporter.buildProperties - enter"}
{"level":20,"time":1714094822417,"name":"sf:elapsedTime","msg":"JUnitReporter.buildProperties - exit","elapsedTime":1.823485}
{"level":20,"time":1714094822417,"name":"sf:elapsedTime","msg":"JUnitReporter.buildTestCases - enter"}
{"level":20,"time":1714094822475,"name":"sf:elapsedTime","msg":"JUnitReporter.buildTestCases - exit","elapsedTime":57.704141}
{"level":20,"time":1714094822475,"name":"sf:elapsedTime","msg":"JUnitReporter.format - exit","elapsedTime":59.935349}
{"level":20,"time":1714094822476,"name":"sf:elapsedTime","msg":"TestService.writeResultFiles - enter"}

mdonnalley commented 1 month ago

Starting with version @salesforce/cli/2.37.4

Could you try installing plugin-apex 3.1.3 (the version used by sf@2.36.8) and see if that resolves the issue? sf plugins install apex@3.1.3

I'm asking because that was the last version before we updated the underlying apex-node library to a new major version. If 3.1.3 works for you then we know that this issue is likely coming from that new major version

Thanks!

pawel-id commented 1 month ago

Could you try installing plugin-apex 3.1.3 (the version used by sf@2.36.8) and see if that resolves the issue? sf plugins install apex@3.1.3

yes, it resolves the issue.

One more observation. I was casually looking at memory consumption of node process while running the command with apex 3.1.3. It seems it is doing some querying of an org for half an hour (code coverage?). During this time memory consumption steadily rose to 400MB. Then rapidly consume 1.7GB and then quit. As I wrote it doesn’t fail, but the memory consumption still seems much too high.

On apex 3.1.11 the memory consumption exceeds 4GB and it fails.

The numbers above are for our project. You are welcome to use scratch orgs provided for debugging the issue.