Skip to content

Conversation

@trentm
Copy link
Member

@trentm trentm commented Apr 18, 2023

It was found that running this test in Docker on mac -- e.g. by running .ci/scripts/test.sh -b release 18 -- would fail. It would hit the set timeout for the execFile call. THis bumps the timeout and improves some logging output around that so it is easier to diagnose if it happens again.

It was found that running this test in Docker on mac -- e.g. by
running `.ci/scripts/test.sh -b release 18` -- would fail. It would
hit the set timeout for the `execFile` call. THis bumps the timeout
and improves some logging output around that so it is easier to
diagnose if it happens again.
@trentm trentm self-assigned this Apr 18, 2023
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Apr 18, 2023
@trentm
Copy link
Member Author

trentm commented Apr 18, 2023

The execFile timeout had been 10s. It was found that on my macos laptop running in Docker Desktop the execFile would take ~13-14s.

Using this patch to gather timing info:

diff --git a/test/instrumentation/modules/aws-sdk/fixtures/use-s3.js b/test/instrumentation/modules/aws-sdk/fixtures/use-s3.js
index 3fdf8e5a..1e1eafa5 100644
--- a/test/instrumentation/modules/aws-sdk/fixtures/use-s3.js
+++ b/test/instrumentation/modules/aws-sdk/fixtures/use-s3.js
@@ -40,6 +40,9 @@
 // Output from a sample run is here:
 // https://gist.github.com/trentm/c402bcab8c0571f26d879ec0bcf5759c

+console.time('use-s3')
+console.timeLog('use-s3', '[use-s3] top')
+
 const apm = require('../../../../..').start({
   serviceName: 'use-s3',
   captureExceptions: false,
@@ -49,11 +52,15 @@ const apm = require('../../../../..').start({
   stackTraceLimit: 4, // get it smaller for reviewing output
   logLevel: 'info'
 })
+console.timeLog('use-s3', '[use-s3] after apm start')

 const crypto = require('crypto')
 const vasync = require('vasync')
+console.timeLog('use-s3', '[use-s3] before aws-sdk require')
 const AWS = require('aws-sdk')
+console.timeLog('use-s3', '[use-s3] after aws-sdk require')
 const assert = require('assert')
+console.timeLog('use-s3', '[use-s3] after all requires')

 const TEST_BUCKET_NAME_PREFIX = 'elasticapmtest-bucket-'

Here is timing from Docker Desktop on Mac:

$ .ci/scripts/test.sh -b "rc" -f 20
...
node_tests_1  | # use-s3: 0.055ms [use-s3] top
node_tests_1  | # use-s3: 1.737s [use-s3] after apm start
node_tests_1  | # use-s3: 1.806s [use-s3] before aws-sdk require
node_tests_1  | # use-s3: 13.260s [use-s3] after aws-sdk require
node_tests_1  | # use-s3: 13.260s [use-s3] after all requires

compared to running directly on my Mac:

% node test/instrumentation/modules/aws-sdk/s3.test.js
...
# use-s3: 0.065ms [use-s3] top
# use-s3: 226.955ms [use-s3] after apm start
# use-s3: 233.407ms [use-s3] before aws-sdk require
# use-s3: 897.404ms [use-s3] after aws-sdk require
# use-s3: 897.509ms [use-s3] after all requires

If I disable RITM (require-in-the-middle) handling, then the timing was closer to:

use-s3: 1.249s [use-s3] after apm
use-s3: 1.290s [use-s3] before require aws-sdk
use-s3: 2.408s [use-s3] after require aws-sdk

So what work is RITM doing? At a guess it is this:

filename = Module._resolveFilename(id, this)

and that is doing file stats and those are DOG SLOW on Docker for Mac.
Not sure, though.

With the added output from this PR, we'll be able to see if it is a concern in CI tests. If not, then this isn't a high enough priority to dig into.

@trentm
Copy link
Member Author

trentm commented Apr 18, 2023

For time comparison, in GH Actions CI for the node 18 test run the timing was:

exec use-s3: 976.25ms

FAR from the 13s in Docker for Mac. So we should be all good here -- this isn't important to dig into.

@trentm trentm merged commit 1273e74 into main Apr 18, 2023
@trentm trentm deleted the trentm/test-fail-docker-mac branch April 18, 2023 23:36
PeterEinberger pushed a commit to fpm-git/apm-agent-nodejs that referenced this pull request Aug 20, 2024
…ic#3276)

It was found that running this test in Docker on mac -- e.g. by
running `.ci/scripts/test.sh -b release 18` -- would fail. It would
hit the set timeout for the `execFile` call. THis bumps the timeout
and improves some logging output around that so it is easier to
diagnose if it happens again.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

agent-nodejs Make available for APM Agents project planning.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants