aws / aws-sdk-js-v3

Modularized AWS SDK for JavaScript.
Apache License 2.0
3.12k stars 578 forks source link

Very slow parallel S3 GetObjectCommand executions (maxSockets) #3560

Open robert-hanuschke opened 2 years ago

robert-hanuschke commented 2 years ago

Describe the bug

Executing many parallel S3 GetObjectCommand is extremely slow in direct comparison to v2 of the sdk at best, suspected of breaking Lambda executions at worst.

Your environment

SDK version number

@aws-sdk/client-s3@3.76.0

Is the issue in the browser/Node.js/ReactNative?

Node.js

Details of the browser/Node.js/ReactNative version

node -v: v14.18.3

Steps to reproduce

I created a bucket containing 159 files (0 byte, size does not seem to be a factor). Then I created the same functionality of getting those files in parallel in minimal scripts for both v3 and v2 of the AWS sdk.

TS Code for v3:

import {
  S3Client,
  GetObjectCommand,
  ListObjectsV2Command,
} from "@aws-sdk/client-s3";

const [nodePath, scriptPath, bucketName] = process.argv;
(async () => {
  try {
    const s3Client = new S3Client({
      region: "us-east-1",
    });
    console.log(new Date().toISOString());
    const files = await s3Client.send(
      new ListObjectsV2Command({
        Bucket: bucketName,
      })
    );
    console.log(new Date().toISOString());
    const getPromises = [];
    if (files.Contents) {
      for (const file of files.Contents) {
        if (file.Key) {
          getPromises.push(
            s3Client.send(
              new GetObjectCommand({
                Bucket: bucketName,
                Key: file.Key,
              })
            )
          );
        }
      }
    }
    const result = await Promise.all(getPromises);
    console.log(result.length);
  } catch (e) {
    console.log(e);
  }
})();

TS Code for v2:

import S3 from "aws-sdk/clients/s3";

const [nodePath, scriptPath, bucketName] = process.argv;

(async () => {
  try {
    const s3Client = new S3({
      region: "us-east-1",
    });
    console.log(new Date().toISOString());
    const files = await s3Client
      .listObjectsV2({
        Bucket: bucketName,
      })
      .promise();
    console.log(new Date().toISOString());

    const getPromises = [];
    if (files.Contents) {
      for (const file of files.Contents) {
        if (file.Key) {
          getPromises.push(
            s3Client.getObject({
              Bucket: bucketName,
              Key: file.Key!,
            }).promise()
          );
        }
      }
    }
    const result = await Promise.all(getPromises)
    console.log(result.length)
  } catch (e) {
    console.log(e);
  }
})();

Observed behavior

After transpiling, I executed both versions multiple times via time node dist/index.js <bucket-name>. There is a huge gap in the execution time between them. I added logs of the timestamp before and after the listObjects command to verify that command isn't the actual issue.

Representative outputs for the difference in execution time I experienced across all runs consistently:

v2

aws-sdk-v2$ time node dist/index.js <bucket-name>
2022-04-25T13:04:08.423Z
2022-04-25T13:04:09.580Z
159

real    0m1,352s
user    0m0,314s
sys 0m0,009s

v3

aws-sdk-v3$ time node dist/index.js <bucket-name>
2022-04-25T13:03:18.831Z
2022-04-25T13:03:19.996Z
159

real    0m27,881s
user    0m1,456s
sys 0m0,176s

On my machine, it's "just" 20 times slower - a lambda function I have which does a similar thing (albeit with more files - around 1100) now after migration from v2 to v3 just returns "null" at that point in the execution when that is not an available return value in any of the execution paths of the code. No error message logged that I could provide unfortunately.

Expected behavior

Similar speed to v2 of the sdk in general, not just ending a Lambda execution.

Screenshots

Additional context

Runi-c commented 2 years ago

Your v2 repro code isn't calling .promise() on the s3Client.getObject(...) calls, so your Promise.all(...) isn't actually waiting for anything. You can confirm this by hovering result and seeing what TypeScript thinks the type is.

robert-hanuschke commented 2 years ago

Thanks a lot for the heads up @Roryl-c , I missed that one. Corrected in an edit above as to send noone down the wrong path. Correcting the code there gets some improvement - we're now still looking at a 12 times worse performance on V3 though.

New representative output (including a console.log of the first element of the result to verify correct operation):

V2:

aws-sdk-v2$ time node dist/index.js <bucket_name>
2022-04-26T04:14:04.309Z
2022-04-26T04:14:05.326Z
159
{
  AcceptRanges: 'bytes',
  LastModified: 2022-04-25T12:48:57.000Z,
  ContentLength: 0,
  ETag: '"d41d8cd98f00b204e9800998ecf8427e"',
  ContentType: 'binary/octet-stream',
  Metadata: {},
  Body: <Buffer >
}

real    0m2,557s
user    0m0,764s
sys 0m0,061s

V3:

Thanks a lot for the heads up @Roryl-c , I missed that one. Corrected in an edit above.
Correcting the code there gets some improvement - we're now still looking at a 12 times worse performance on v3 though.

aws-sdk-v3$ time node dist/index.js <bucket_name>
2022-04-26T04:14:23.927Z
2022-04-26T04:14:25.164Z
159
{
  '$metadata': {
    httpStatusCode: 200,
    requestId: undefined,
    extendedRequestId: 'oaX1SPWbVP+SbotZ5EtrxulYZEMyVU8+JtrrjpoGHi1pXXQsxWvBqjy8V2uQ99SkpmxI1wS1+cE=',
    cfId: undefined,
    attempts: 1,
    totalRetryDelay: 0
  },
  AcceptRanges: 'bytes',
  Body: <ref *1> IncomingMessage {
    _readableState: ReadableState {
      objectMode: false,
      highWaterMark: 16384,
      buffer: BufferList { head: null, tail: null, length: 0 },
      length: 0,
      pipes: [],
      flowing: null,
      ended: true,
      endEmitted: false,
      reading: false,
      sync: true,
      needReadable: false,
      emittedReadable: false,
      readableListening: false,
      resumeScheduled: false,
      errorEmitted: false,
      emitClose: true,
      autoDestroy: false,
      destroyed: false,
      errored: null,
      closed: false,
      closeEmitted: false,
      defaultEncoding: 'utf8',
      awaitDrainWriters: null,
      multiAwaitDrain: false,
      readingMore: true,
      dataEmitted: false,
      decoder: null,
      encoding: null,
      [Symbol(kPaused)]: null
    },
    _events: [Object: null prototype] { end: [Array] },
    _eventsCount: 1,
    _maxListeners: undefined,
    socket: TLSSocket {
      _tlsOptions: [Object],
      _secureEstablished: true,
      _securePending: false,
      _newSessionPending: false,
      _controlReleased: true,
      secureConnecting: false,
      _SNICallback: null,
      servername: '<bucket_name>.s3.us-east-1.amazonaws.com',
      alpnProtocol: false,
      authorized: true,
      authorizationError: null,
      encrypted: true,
      _events: [Object: null prototype],
      _eventsCount: 9,
      connecting: false,
      _hadError: false,
      _parent: null,
      _host: '<bucket_name>.s3.us-east-1.amazonaws.com',
      _readableState: [ReadableState],
      _maxListeners: undefined,
      _writableState: [WritableState],
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: undefined,
      _server: null,
      ssl: null,
      _requestCert: true,
      _rejectUnauthorized: true,
      parser: null,
      _httpMessage: [ClientRequest],
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(res)]: null,
      [Symbol(verified)]: true,
      [Symbol(pendingSession)]: null,
      [Symbol(async_id_symbol)]: 48,
      [Symbol(kHandle)]: null,
      [Symbol(kSetNoDelay)]: false,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: null,
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kCapture)]: false,
      [Symbol(kBytesRead)]: 34826,
      [Symbol(kBytesWritten)]: 3387,
      [Symbol(connect-options)]: [Object],
      [Symbol(RequestTimeout)]: undefined
    },
    httpVersionMajor: 1,
    httpVersionMinor: 1,
    httpVersion: '1.1',
    complete: true,
    headers: {
      'x-amz-id-2': 'oaX1SPWbVP+SbotZ5EtrxulYZEMyVU8+JtrrjpoGHi1pXXQsxWvBqjy8V2uQ99SkpmxI1wS1+cE=',
      'x-amz-request-id': '8YZSWGXFWP7F92XJ',
      date: 'Tue, 26 Apr 2022 04:14:26 GMT',
      'last-modified': 'Mon, 25 Apr 2022 12:48:57 GMT',
      etag: '"d41d8cd98f00b204e9800998ecf8427e"',
      'accept-ranges': 'bytes',
      'content-type': 'binary/octet-stream',
      server: 'AmazonS3',
      'content-length': '0'
    },
    rawHeaders: [
      'x-amz-id-2',
      'oaX1SPWbVP+SbotZ5EtrxulYZEMyVU8+JtrrjpoGHi1pXXQsxWvBqjy8V2uQ99SkpmxI1wS1+cE=',
      'x-amz-request-id',
      '8YZSWGXFWP7F92XJ',
      'Date',
      'Tue, 26 Apr 2022 04:14:26 GMT',
      'Last-Modified',
      'Mon, 25 Apr 2022 12:48:57 GMT',
      'ETag',
      '"d41d8cd98f00b204e9800998ecf8427e"',
      'Accept-Ranges',
      'bytes',
      'Content-Type',
      'binary/octet-stream',
      'Server',
      'AmazonS3',
      'Content-Length',
      '0'
    ],
    trailers: {},
    rawTrailers: [],
    aborted: false,
    upgrade: false,
    url: '',
    method: null,
    statusCode: 200,
    statusMessage: 'OK',
    client: TLSSocket {
      _tlsOptions: [Object],
      _secureEstablished: true,
      _securePending: false,
      _newSessionPending: false,
      _controlReleased: true,
      secureConnecting: false,
      _SNICallback: null,
      servername: '<bucket_name>.s3.us-east-1.amazonaws.com',
      alpnProtocol: false,
      authorized: true,
      authorizationError: null,
      encrypted: true,
      _events: [Object: null prototype],
      _eventsCount: 9,
      connecting: false,
      _hadError: false,
      _parent: null,
      _host: '<bucket_name>.s3.us-east-1.amazonaws.com',
      _readableState: [ReadableState],
      _maxListeners: undefined,
      _writableState: [WritableState],
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: undefined,
      _server: null,
      ssl: null,
      _requestCert: true,
      _rejectUnauthorized: true,
      parser: null,
      _httpMessage: [ClientRequest],
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(res)]: null,
      [Symbol(verified)]: true,
      [Symbol(pendingSession)]: null,
      [Symbol(async_id_symbol)]: 48,
      [Symbol(kHandle)]: null,
      [Symbol(kSetNoDelay)]: false,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: null,
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kCapture)]: false,
      [Symbol(kBytesRead)]: 34826,
      [Symbol(kBytesWritten)]: 3387,
      [Symbol(connect-options)]: [Object],
      [Symbol(RequestTimeout)]: undefined
    },
    _consuming: false,
    _dumped: false,
    req: ClientRequest {
      _events: [Object: null prototype],
      _eventsCount: 4,
      _maxListeners: undefined,
      outputData: [],
      outputSize: 0,
      writable: true,
      destroyed: true,
      _last: true,
      chunkedEncoding: false,
      shouldKeepAlive: true,
      _defaultKeepAlive: true,
      useChunkedEncodingByDefault: false,
      sendDate: false,
      _removedConnection: false,
      _removedContLen: false,
      _removedTE: false,
      _contentLength: 0,
      _hasBody: true,
      _trailer: '',
      finished: true,
      _headerSent: true,
      socket: [TLSSocket],
      _header: '<REDACTED>',
      _keepAliveTimeout: 0,
      _onPendingData: [Function: noopPendingOutput],
      agent: [Agent],
      socketPath: undefined,
      method: 'GET',
      maxHeaderSize: undefined,
      insecureHTTPParser: undefined,
      path: '/027f19cca4a7119da720?x-id=GetObject',
      _ended: false,
      res: [Circular *1],
      aborted: false,
      timeoutCb: [Function: emitRequestTimeout],
      upgradeOrConnect: false,
      parser: null,
      maxHeadersCount: null,
      reusedSocket: true,
      host: '<bucket_name>.s3.us-east-1.amazonaws.com',
      protocol: 'https:',
      [Symbol(kCapture)]: false,
      [Symbol(kNeedDrain)]: false,
      [Symbol(corked)]: 0,
      [Symbol(kOutHeaders)]: [Object: null prototype]
    },
    [Symbol(kCapture)]: false,
    [Symbol(RequestTimeout)]: undefined
  },
  BucketKeyEnabled: undefined,
  CacheControl: undefined,
  ChecksumCRC32: undefined,
  ChecksumCRC32C: undefined,
  ChecksumSHA1: undefined,
  ChecksumSHA256: undefined,
  ContentDisposition: undefined,
  ContentEncoding: undefined,
  ContentLanguage: undefined,
  ContentLength: 0,
  ContentRange: undefined,
  ContentType: 'binary/octet-stream',
  DeleteMarker: undefined,
  ETag: '"d41d8cd98f00b204e9800998ecf8427e"',
  Expiration: undefined,
  Expires: undefined,
  LastModified: 2022-04-25T12:48:57.000Z,
  Metadata: {},
  MissingMeta: undefined,
  ObjectLockLegalHoldStatus: undefined,
  ObjectLockMode: undefined,
  ObjectLockRetainUntilDate: undefined,
  PartsCount: undefined,
  ReplicationStatus: undefined,
  RequestCharged: undefined,
  Restore: undefined,
  SSECustomerAlgorithm: undefined,
  SSECustomerKeyMD5: undefined,
  SSEKMSKeyId: undefined,
  ServerSideEncryption: undefined,
  StorageClass: undefined,
  TagCount: undefined,
  VersionId: undefined,
  WebsiteRedirectLocation: undefined
}

real    0m28,922s
user    0m1,799s
sys 0m0,213s

Also crosschecked the Lambda code I mentioned, thankfully didn't miss the .promise() in the V2 implementation there. After reverting to V2 just for that specific functionality (the rest of the Lambda still runs on V3), it works again.

RanVaknin commented 2 years ago

@robert-hanuschke Hi! Thanks for bringing this to our attention.

I was able to reproduce your findings observing these 2 scenarios:

Running the code for 87 items in S3 bucket: V3:

Time isntantiate s3 client: 136.60179090499878ms
Time to list objects in bucket: 654.9991250038147ms
87 subsequent GetObject calls:  7387.941290855408ms

V2:

Time isntantiate s3 client: 79.35779213905334ms
Time to list objects in bucket: 646.8728330135345ms
87 subsequent GetObject calls:  861.3942501544952ms

Running the code with 1 item in S3 bucket: V3:

Time isntantiate s3 client: 138.31212520599365ms
Time to list objects in bucket: 498.3790419101715ms
1 subsequent GetObject calls:  251.10545825958252 ms

V2:

Time isntantiate s3 client: 99.40116715431213ms
Time to list objects in bucket: 535.6090829372406ms
1 subsequent GetObject calls:  524.4567511081696ms 

It appears that fetching more subsequent calls causes performance issues in V3, however single or fewer reads are faster in V3. @trivikr, based on your suggestion I have inspected the CPU usage of the provided example and found out that for the multiple item reads from the bucket is in fact a subsequent call of getOjectCommand, more specifically: @aws-sdk/node-http-handler/dist-cjs/node-http-handler.js 49:28

Im forwarding it to the dev team for further investigation.

RanVaknin commented 2 years ago

Hi @robert-hanuschke ,

I recognize that these kind of edge cases can be frustrating; however, we prioritize fixes and features based on community engagement and feedback. At this time there is no plan to address this issue. If anything changes I will certainly let you know.

Many thanks!

robert-hanuschke commented 2 years ago

Hi Ran,

thanks for reopening. I was worried it would be completely forgotten if closed. It having lower priority if it's an edge case I totally understand.

For the time being I can live with the workaround of having this call still on the old sdk and hope this issue helps people stumbling across it who are in the same situation.

samjarman commented 2 years ago

I have witnessed something similar. Many keys retrieved my making an array of promises, where each promise reuses the same client and sends a GetObjectCommand instance will execute what seems like in sequence, instead of "in parallel" like we'd expect from promise.all.

What I can add though, is when in the same promise, I iterate through the stream and convert to a buffer, then the promises are properly executed in what seems like parallel.

A minimal code example here:

import { GetObjectCommand, S3Client } from '@aws-sdk/client-s3';
import { Readable } from 'stream';
import { BUCKET, KEYS } from './keys';

export function streamToBuffer(stream: Readable): Promise<Buffer> {
    return new Promise((resolve, reject) => {
        const chunks: Uint8Array[] = [];
        stream.on('data', (chunk) => chunks.push(chunk));
        stream.on('error', reject);
        stream.on('end', () => resolve(Buffer.concat(chunks)));
    });
}

export async function getObjectsFast(client: S3Client, bucket: string, keys: string[]): Promise<any[]> { 
    return Promise.all(keys.map(key => getObjectFast(client, bucket, key)));
}

async function getObjectFast(client: S3Client, bucket: string, key: string): Promise<any> {
    const command = new GetObjectCommand({ Bucket: bucket, Key: key });
    const result = await client.send(command);
    const buffer = await streamToBuffer(result.Body as Readable);
    return buffer;
}

async function getObjectSlow(client: S3Client, bucket: string, key: string): Promise<any> {
    const command = new GetObjectCommand({ Bucket: bucket, Key: key });
    const result = await client.send(command);
    return result;
}

export async function getObjectsSlow(client: S3Client, bucket: string, keys: string[]): Promise<any[]> { 
    return Promise.all(keys.map(key => getObjectSlow(client, bucket, key)));
}

async function run() {
    const client = new S3Client({ region: 'ap-southeast-2' });
    console.log(KEYS.length); // 75
    const t1 = new Date();
    await getObjectsFast(client, BUCKET, KEYS);
    console.log('took1:', new Date().valueOf() - t1.valueOf()); // 260

    const t2 = new Date();
    await getObjectsSlow(client, BUCKET, KEYS);
    console.log('took2:', new Date().valueOf() - t2.valueOf()); //6200
}

void run();

3.121.0 of the lib Node v14.17.6

rijkvanzanten commented 1 year ago

I recently ran into a very similar situation, where doing a lot of GetObjectCommands in rapid succession would slow down tremendously and eventually lock up the process. Our current workaround is to make a new client instance for each GetObjectCommand and destroying it as soon as the read is done:

// Before
const client = new S3Client();

async function getFileStream() {
  const response = await client.send(new GetObjectCommand({ Bucket, Key }));
  return response.Body;
}

// After
async function getFileStream() {
  const client = new S3Client();
  const response = await client.send(new GetObjectCommand({ Bucket, Key }));
  response.Body.on('finished', () => client.destroy());
  return response.Body;
}

I thought that the issue before might've been caused by the default keepAlive behavior of the SDK, but explicitly disabling that and lowering the maxSockets didn't seem to resolve the problem fully 🤔

askldjd commented 1 year ago

@rijkvanzanten

I was able to reproduce this issue recently and found a solution. The problem as I can see comes from two areas:

  1. a small default socket pool from the HTTPS agent
  2. the lack of socket timeout that may leak sockets from certain scenarios (e.g. if you pipe the response.Body to another stream and the other stream dies prematurely)

Once the HTTP Agent sockets are all in use, the S3Clients will hang. Your "new client per instance" will work, but you pay a big performance penalty for the huge resource allocations for every request, and losing the TLS session cache and HTTP keep-alive.

Here's a setting I find that works in my environment. You can tune the maxSockets and socketTimeout to your environment.

const s3 = new S3Client({
  // Use a custom request handler so that we can adjust the HTTPS Agent and
  // socket behavior.
  requestHandler: new NodeHttpHandler({
    httpsAgent: new Agent({
      maxSockets: 500,

      // keepAlive is a default from AWS SDK. We want to preserve this for
      // performance reasons.
      keepAlive: true,
      keepAliveMsecs: 1000,
    }),
    socketTimeout: 5000,
  }),
});
rijkvanzanten commented 1 year ago

Great solution @askldjd! Thanks for sharing 😄 Very curious to see what changed between v2 and v3 in the handling of those sockets which now causes the socket to hang rather than cleanup.

askldjd commented 1 year ago

That's a good question. If I am reading correctly, V2 defaults the timeout to 2 minutes. However, V3 defaults the timeout to zero.

That might be the root cause.

RanVaknin commented 1 year ago

Hi everyone,

Thank you for continuing commenting and providing information. @samjarman Thank you for the repro code, and @askldjd thanks for the workaround. I was able to confirm the described behavior (finally) and noticed that the performance increased with the suggested agent config. We are looking into this with priority.

Thank you for all for your help! Ran~

RanVaknin commented 1 year ago

Node profiler output comparing v2 and v3

V3 Profile ```console Statistical profiling result from isolate-0x128040000-67002-v8.log, (1481 ticks, 12 unaccounted, 0 excluded). [Shared libraries]: ticks total nonlib name 64 4.3% /usr/lib/system/libsystem_malloc.dylib 17 1.1% /usr/lib/system/libsystem_pthread.dylib 11 0.7% /usr/lib/system/libsystem_c.dylib 5 0.3% /usr/lib/system/libsystem_platform.dylib 4 0.3% /usr/lib/libc++.1.dylib 1 0.1% /usr/lib/system/libsystem_kernel.dylib 1 0.1% /usr/lib/libobjc.A.dylib 1 0.1% /usr/lib/libc++abi.dylib [JavaScript]: ticks total nonlib name 1 0.1% 0.1% RegExp: ^((?:(?:[0-9a-fA-F]{1,4}):){7}(?:(?:[0-9a-fA-F]{1,4})|:)|(?:(?:[0-9a-fA-F]{1,4}):){6}(?:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|:(?:[0-9a-fA-F]{1,4})|:)|(?:(?:[0-9a-fA-F]{1,4}):){5}(?::((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(:(?:[0-9a-fA-F]{1,4})){1,2}|:)|(?:(?:[0-9a-fA-F]{1,4}):){4}(?:(:(?:[0-9a-fA-F]{1,4})){0,1}:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(:(?:[0-9a-fA-F]{1,4})){1,3}|:)|(?:(?:[0-9a-fA-F]{1,4}):){3}(?:(:(?:[0-9a-fA-F]{1,4})){0,2}:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(:(?:[0-9a-fA-F]{1,4})){1,4}|:)|(?:(?:[0-9a-fA-F]{1,4}):){2}(?:(:(?:[0-9a-fA-F]{1,4})){0,3}:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(:(?:[0-9a-fA-F]{1,4})){1,5}|:)|(?:(?:[0-9a-fA-F]{1,4}):){1}(?:(:(?:[0-9a-fA-F]{1,4})){0,4}:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(:(?:[0-9a-fA-F]{1,4})){1,6}|:)|(?::((?::(?:[0-9a-fA-F]{1,4})){0,5}:((?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])[.]){3}(?:[0-9]|[1-9][0-9]|1[0-9][0-9]|2[0-4][0-9]|25[0-5])|(?::(?:[0-9a-fA-F]{1,4})){1,7}|:)))(%[0-9a-zA-Z-.:]{1,})?$ 1 0.1% 0.1% RegExp: (^|\\|\/)((\.|%2e)(\.|%2e)?|(n|%6e|%4e)(o|%6f|%4f)(d|%64|%44)(e|%65|%45)(_|%5f)(m|%6d|%4d)(o|%6f|%4f)(d|%64|%44)(u|%75|%55)(l|%6c|%4c)(e|%65|%45)(s|%73|%53))?(\\|\/|$) 1 0.1% 0.1% LazyCompile: *resolve node:path:1091:10 1 0.1% 0.1% LazyCompile: *applyInstruction /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/object-mapping.js:65:26 1 0.1% 0.1% LazyCompile: *C node:internal/deps/cjs-module-lexer/dist/lexer:1:1152 1 0.1% 0.1% Function: ^resolveParams /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-endpoint/dist-cjs/adaptors/getEndpointFromInstructions.js:15:23 1 0.1% 0.1% Function: ^processTicksAndRejections node:internal/process/task_queues:67:35 1 0.1% 0.1% Function: ^onFree node:_http_agent:384:18 1 0.1% 0.1% Function: ^nextTick node:internal/process/task_queues:103:18 1 0.1% 0.1% Function: ^isUint8Array node:internal/util/types:13:22 1 0.1% 0.1% Function: ^getEncodingOps node:buffer:688:24 1 0.1% 0.1% Function: ^evaluateRules /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/util-endpoints/dist-cjs/utils/evaluateRules.js:8:23 1 0.1% 0.1% Function: ^emitAfterScript node:internal/async_hooks:517:25 1 0.1% 0.1% Function: ^dirname node:path:1275:10 1 0.1% 0.1% Function: ^createSocket node:_http_agent:319:53 1 0.1% 0.1% Function: ^ node:internal/validators:138:40 [C++]: ticks total nonlib name 725 49.0% 52.7% T node::contextify::ContextifyScript::~ContextifyScript() 350 23.6% 25.4% T _posix_spawnattr_setflags 87 5.9% 6.3% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 52 3.5% 3.8% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 26 1.8% 1.9% T _sigprocmask 17 1.1% 1.2% T _semaphore_destroy 13 0.9% 0.9% T _mach_port_insert_member 11 0.7% 0.8% t __pthread_cond_check_init_slow 10 0.7% 0.7% T _mach_vm_protect 10 0.7% 0.7% T __kernelrpc_mach_port_move_member_trap 9 0.6% 0.7% T node::HandleWrap::Close(v8::FunctionCallbackInfo const&) 6 0.4% 0.4% T _mach_timebase_info_trap 6 0.4% 0.4% T ___bsdthread_terminate 3 0.2% 0.2% t __os_once_gate_wait 2 0.1% 0.1% t std::__1::ostreambuf_iterator > std::__1::__pad_and_output >(std::__1::ostreambuf_iterator >, char const*, char const*, char const*, std::__1::ios_base&, char) 2 0.1% 0.1% t node::Environment::StartProfilerIdleNotifier()::$_6::__invoke(uv_check_s*) 2 0.1% 0.1% t __pthread_mutex_firstfit_unlock_slow 2 0.1% 0.1% t __os_nospin_lock_unlock_slow 2 0.1% 0.1% t ___pfz_setup 2 0.1% 0.1% T _qos_class_main 2 0.1% 0.1% T _mach_port_insert_right 2 0.1% 0.1% T __kernelrpc_mach_port_get_refs 1 0.1% 0.1% T node::loader::ModuleWrap::New(v8::FunctionCallbackInfo const&) 1 0.1% 0.1% T node::InternalCallbackScope::~InternalCallbackScope() 1 0.1% 0.1% T node::Emit(node::Environment*, double, node::AsyncHooks::Fields, v8::Local) 1 0.1% 0.1% T node::AsyncHooks::push_async_context(double, double, v8::Local) 1 0.1% 0.1% T _pthread_mutex_init 1 0.1% 0.1% T _mach_port_deallocate 1 0.1% 0.1% T __os_semaphore_create 1 0.1% 0.1% T __kernelrpc_mach_vm_map [Summary]: ticks total nonlib name 16 1.1% 1.2% JavaScript 1349 91.1% 98.0% C++ 61 4.1% 4.4% GC 104 7.0% Shared libraries 12 0.8% Unaccounted [C++ entry points]: ticks cpp total name 567 75.5% 38.3% T node::contextify::ContextifyScript::~ContextifyScript() 87 11.6% 5.9% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 52 6.9% 3.5% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 14 1.9% 0.9% T _sigprocmask 9 1.2% 0.6% T node::HandleWrap::Close(v8::FunctionCallbackInfo const&) 8 1.1% 0.5% T __kernelrpc_mach_port_move_member_trap 7 0.9% 0.5% T node::loader::ModuleWrap::Evaluate(v8::FunctionCallbackInfo const&) 2 0.3% 0.1% t std::__1::ostreambuf_iterator > std::__1::__pad_and_output >(std::__1::ostreambuf_iterator >, char const*, char const*, char const*, std::__1::ios_base&, char) 2 0.3% 0.1% t ___pfz_setup 1 0.1% 0.1% t __os_nospin_lock_unlock_slow 1 0.1% 0.1% T node::loader::ModuleWrap::New(v8::FunctionCallbackInfo const&) 1 0.1% 0.1% T __kernelrpc_mach_port_get_refs [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. Callers occupying less than 1.0% are not shown. ticks parent name 725 49.0% T node::contextify::ContextifyScript::~ContextifyScript() 124 17.1% Function: ^TLSSocket.getPeerCertificate node:_tls_wrap:999:50 118 95.2% Function: ^onConnectSecure node:_tls_wrap:1531:25 93 78.8% Function: ^emit node:events:460:44 93 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 93 100.0% Function: ^ssl.onhandshakedone node:_tls_wrap:741:27 25 21.2% LazyCompile: *emit node:events:460:44 25 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 25 100.0% Function: ^ssl.onhandshakedone node:_tls_wrap:741:27 6 4.8% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 6 100.0% Function: ^emit node:events:460:44 6 100.0% LazyCompile: ~TLSSocket._finishInit node:_tls_wrap:933:43 6 100.0% Function: ^ssl.onhandshakedone node:_tls_wrap:741:27 59 8.1% Function: ^readSync node:fs:705:18 59 100.0% Function: ^tryReadSync node:fs:444:21 59 100.0% Function: ^readFileSync node:fs:465:22 41 69.5% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 41 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 9 15.3% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 8 88.9% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 11.1% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 9 15.3% Function: ^cjsPreparseModuleExports node:internal/modules/esm/translators:193:34 9 100.0% Function: ^ node:internal/modules/esm/translators:232:36 27 3.7% Function: ^SecureContext node:_tls_common:75:23 27 100.0% Function: ^createSecureContext node:_tls_common:99:29 27 100.0% Function: ^connect node:_tls_wrap:1612:35 27 100.0% Function: ^createConnection node:https:118:26 27 100.0% Function: ^createSocket node:_http_agent:319:53 26 3.6% Function: ^TLSSocket._init node:_tls_wrap:685:37 26 100.0% Function: ^TLSSocket node:_tls_wrap:470:19 26 100.0% Function: ^connect node:_tls_wrap:1612:35 26 100.0% Function: ^createConnection node:https:118:26 26 100.0% Function: ^createSocket node:_http_agent:319:53 22 3.0% Function: ^methodProxy node:_tls_wrap:560:30 21 95.5% Function: ^internalConnect node:net:1003:25 21 100.0% Function: ^defaultTriggerAsyncIdScope node:internal/async_hooks:455:36 21 100.0% Function: ^emitLookup node:net:1293:46 21 100.0% Function: ^onlookup node:dns:105:18 1 4.5% LazyCompile: ~internalConnect node:net:1003:25 1 100.0% Function: ^defaultTriggerAsyncIdScope node:internal/async_hooks:455:36 1 100.0% Function: ^emitLookup node:net:1293:46 1 100.0% LazyCompile: ~onlookup node:dns:105:18 21 2.9% T node::contextify::ContextifyScript::~ContextifyScript() 2 9.5% T node::contextify::ContextifyScript::~ContextifyScript() 1 50.0% Function: ^stat node:internal/modules/cjs/loader:161:14 1 100.0% Function: ^tryFile node:internal/modules/cjs/loader:440:17 1 100.0% Function: ^tryExtensions node:internal/modules/cjs/loader:456:23 1 50.0% Function: ^readPackage node:internal/modules/cjs/loader:335:21 1 100.0% Function: ^readPackageScope node:internal/modules/cjs/loader:377:26 1 100.0% LazyCompile: ~trySelf node:internal/modules/cjs/loader:497:17 2 9.5% Function: ^splitHost node:tls:170:19 2 100.0% Function: ^check node:tls:177:15 2 100.0% Function: ^wildcard node:tls:313:22 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 2 9.5% Function: ^processCiphers node:internal/tls/secure-context:95:24 2 100.0% Function: ^configSecureContext node:internal/tls/secure-context:124:29 2 100.0% Function: ^createSecureContext node:_tls_common:99:29 2 100.0% Function: ^connect node:_tls_wrap:1612:35 2 9.5% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 2 100.0% Function: ^require node:internal/modules/cjs/helpers:102:31 1 50.0% Function: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/hash-stream-node/dist-cjs/HashCalculator.js:1:1 1 50.0% Function: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-sso-oidc/dist-cjs/index.js:1:1 2 9.5% Function: ^Module._findPath node:internal/modules/cjs/loader:555:28 2 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 2 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 4.8% LazyCompile: ~parseRfc7231DateTime /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/date-utils.js:67:30 1 100.0% LazyCompile: ~contents.LastModified /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-s3/dist-cjs/protocols/Aws_restXml.js:4231:13 1 100.0% Function: ^applyInstruction /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/object-mapping.js:65:26 1 100.0% Function: ^map /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/object-mapping.js:4:13 1 4.8% LazyCompile: ~getProfileData /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/shared-ini-file-loader/dist-cjs/getProfileData.js:5:24 1 4.8% LazyCompile: *callFunction /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/util-endpoints/dist-cjs/utils/callFunction.js:7:22 1 100.0% Function: ^evaluateCondition /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/util-endpoints/dist-cjs/utils/evaluateCondition.js:7:27 1 100.0% Function: ^evaluateConditions /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/util-endpoints/dist-cjs/utils/evaluateConditions.js:6:28 1 100.0% Function: ^evaluateEndpointRule /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/util-endpoints/dist-cjs/utils/evaluateEndpointRule.js:9:30 1 4.8% Function: ~ node:internal/net:1:1 1 100.0% Function: ~ node:internal/dns/utils:1:1 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 4.8% Function: ^realpathSync node:fs:2474:22 1 100.0% Function: ^toRealPath node:internal/modules/cjs/loader:449:20 1 100.0% Function: ^tryFile node:internal/modules/cjs/loader:440:17 1 100.0% Function: ^tryExtensions node:internal/modules/cjs/loader:456:23 1 4.8% Function: ^readPackage node:internal/modules/cjs/loader:335:21 1 100.0% Function: ^readPackageScope node:internal/modules/cjs/loader:377:26 1 100.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 4.8% Function: ^getOwn node:internal/bootstrap/loaders:188:16 1 100.0% Function: ^syncExports node:internal/bootstrap/loaders:307:14 1 100.0% LazyCompile: ~ node:internal/bootstrap/loaders:293:15 1 100.0% T node::loader::ModuleWrap::Evaluate(v8::FunctionCallbackInfo const&) 1 4.8% Function: ^getMiddlewareList /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-stack/dist-cjs/MiddlewareStack.js:69:31 1 100.0% Function: ^resolve /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-stack/dist-cjs/MiddlewareStack.js:202:18 1 100.0% Function: ^resolveMiddleware /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-s3/dist-cjs/commands/GetObjectCommand.js:30:22 1 100.0% Function: ^send /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/client.js:10:9 1 4.8% Function: ^createCanonicalRequest /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/signature-v4/dist-cjs/SignatureV4.js:110:27 1 100.0% Function: ^signRequest /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/signature-v4/dist-cjs/SignatureV4.js:86:22 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 4.8% Function: ^checkServerIdentity node:tls:280:59 1 100.0% Function: ^onConnectSecure node:_tls_wrap:1531:25 1 100.0% Function: ^emit node:events:460:44 1 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 1 4.8% Function: ^check node:tls:177:15 1 100.0% Function: ^wildcard node:tls:313:22 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% Function: ^checkServerIdentity node:tls:280:59 21 2.9% Function: ^TLSSocket._start node:_tls_wrap:962:38 21 100.0% Function: ^onceWrapper node:events:622:21 20 95.2% Function: ^emit node:events:460:44 20 100.0% Function: ^afterConnect node:net:1440:22 1 4.8% LazyCompile: *emit node:events:460:44 1 100.0% Function: ^afterConnect node:net:1440:22 16 2.2% Function: ^TLSSocket.setSession node:_tls_wrap:993:42 16 100.0% Function: ^connect node:_tls_wrap:1612:35 16 100.0% Function: ^createConnection node:https:118:26 16 100.0% Function: ^createSocket node:_http_agent:319:53 16 100.0% Function: ^removeSocket node:_http_agent:433:53 14 1.9% LazyCompile: ~configSecureContext node:internal/tls/secure-context:124:29 14 100.0% LazyCompile: ~createSecureContext node:_tls_common:99:29 14 100.0% LazyCompile: ~connect node:_tls_wrap:1612:35 14 100.0% LazyCompile: ~createConnection node:https:118:26 14 100.0% LazyCompile: ~createSocket node:_http_agent:319:53 13 1.8% Function: ^done node:_tls_wrap:579:16 9 1.2% Function: ^openSync node:fs:591:18 9 100.0% Function: ^readFileSync node:fs:465:22 7 77.8% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 7 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 7 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 11.1% LazyCompile: ~Module._extensions..json node:internal/modules/cjs/loader:1277:39 1 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 11.1% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% LazyCompile: ~Module._load node:internal/modules/cjs/loader:851:24 8 1.1% LazyCompile: ~TLSSocket.getPeerCertificate node:_tls_wrap:999:50 8 100.0% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 8 100.0% Function: ^emit node:events:460:44 8 100.0% LazyCompile: ~TLSSocket._finishInit node:_tls_wrap:933:43 8 100.0% LazyCompile: ~ssl.onhandshakedone node:_tls_wrap:741:27 350 23.6% T _posix_spawnattr_setflags 87 5.9% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 83 95.4% Function: ^internalCompileFunction node:internal/vm:30:33 65 78.3% Function: ^wrapSafe node:internal/modules/cjs/loader:1117:18 65 100.0% Function: ^Module._compile node:internal/modules/cjs/loader:1173:37 65 100.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 65 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 18 21.7% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 16 88.9% Function: ^Module._compile node:internal/modules/cjs/loader:1173:37 16 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 16 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 2 11.1% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 2 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 2 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 4 4.6% LazyCompile: ~internalCompileFunction node:internal/vm:30:33 4 100.0% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 4 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 4 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 4 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 64 4.3% /usr/lib/system/libsystem_malloc.dylib 2 3.1% T node::contextify::ContextifyScript::~ContextifyScript() 1 50.0% LazyCompile: ~getMiddlewareList /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-stack/dist-cjs/MiddlewareStack.js:69:31 1 100.0% LazyCompile: ~resolve /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-stack/dist-cjs/MiddlewareStack.js:202:18 1 100.0% LazyCompile: ~resolveMiddleware /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-s3/dist-cjs/commands/GetObjectCommand.js:30:22 1 100.0% LazyCompile: ~send /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/client.js:10:9 1 50.0% Function: ^Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 1.6% LazyCompile: ~parserOnIncomingClient node:_http_client:607:32 1 100.0% LazyCompile: ~parserOnHeadersComplete node:_http_common:72:33 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~socketOnData node:_http_client:529:22 1 100.0% Function: ^emit node:events:460:44 1 1.6% LazyCompile: ~getDefaultRoleAssumer /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-sts/dist-cjs/defaultRoleAssumers.js:19:31 1 100.0% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-sts/dist-cjs/defaultRoleAssumers.js:23:57 1 100.0% LazyCompile: ~resolveAwsAuthConfig /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-signing/dist-cjs/configurations.js:8:30 1 100.0% LazyCompile: ~S3Client /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-s3/dist-cjs/S3Client.js:20:16 1 100.0% LazyCompile: ~run file:///Users/rvaknin/test_folder/3560a/sample.js:44:19 1 1.6% LazyCompile: ~_finish node:_http_client:369:51 1 100.0% Function: ^_flush node:_http_outgoing:1077:51 1 100.0% LazyCompile: ~onSocketNT node:_http_client:866:20 1 100.0% Function: ^processTicksAndRejections node:internal/process/task_queues:67:35 1 1.6% LazyCompile: ~Module._extensions..json node:internal/modules/cjs/loader:1277:39 1 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 100.0% Function: ^require node:internal/modules/cjs/helpers:102:31 1 1.6% LazyCompile: ~ node:internal/validators:288:39 1 100.0% LazyCompile: ~internalCompileFunction node:internal/vm:30:33 1 100.0% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 1 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 1 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 1.6% Function: ^createConnection node:https:118:26 1 100.0% Function: ^createSocket node:_http_agent:319:53 1 100.0% LazyCompile: ~removeSocket node:_http_agent:433:53 1 100.0% LazyCompile: ~onClose node:_http_agent:390:19 1 100.0% Function: ^emit node:events:460:44 52 3.5% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 33 63.5% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 28 84.8% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 5 17.9% Function: ~ node:http2:1:1 5 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 5 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 4 14.3% Function: ~ node:https:1:1 4 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 4 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 3 10.7% Function: ~ node:tls:1:1 3 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 3 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.1% Function: ~ node:internal/http2/core:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.1% Function: ~ node:internal/child_process:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.1% Function: ~ node:assert:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.1% Function: ~ node:_http_server:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.6% LazyCompile: ~lookupAndConnect node:net:1202:26 1 100.0% LazyCompile: ~Socket.connect node:net:1134:36 1 100.0% LazyCompile: ~connect node:_tls_wrap:1612:35 1 3.6% LazyCompile: ~lazyWebCrypto node:crypto:125:23 1 100.0% LazyCompile: ~get node:crypto:369:8 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 3.6% LazyCompile: ~lazyLoadStreams node:fs:2907:25 1 100.0% LazyCompile: ~get ReadStream node:fs:3050:17 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 3.6% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 3.6% LazyCompile: ~initCJSParse node:internal/modules/esm/translators:58:28 1 100.0% LazyCompile: ~commonjsStrategy node:internal/modules/esm/translators:147:60 1 100.0% LazyCompile: ~moduleProvider node:internal/modules/esm/loader:452:28 1 3.6% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 100.0% LazyCompile: ~refresh node:internal/util/colors:10:10 1 3.6% Function: ~ node:internal/http2/compat:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.6% Function: ~ node:child_process:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 5 15.2% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 4 80.0% Function: ^loadBuiltinModule node:internal/modules/cjs/helpers:45:27 4 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 4 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 20.0% LazyCompile: ~loadBuiltinModule node:internal/modules/cjs/helpers:45:27 1 100.0% LazyCompile: ~builtinStrategy node:internal/modules/esm/translators:253:58 1 100.0% LazyCompile: ~moduleProvider node:internal/modules/esm/loader:452:28 3 5.8% Function: ~ node:internal/modules/esm/loader:1:1 3 100.0% Function: ~ node:internal/process/esm_loader:1:1 3 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 3 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 3 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 3 5.8% Function: ~ node:internal/modules/esm/fetch_module:1:1 3 100.0% Function: ~ node:internal/modules/esm/get_format:1:1 3 100.0% Function: ~ node:internal/modules/esm/resolve:1:1 3 100.0% Function: ~ node:internal/modules/esm/loader:1:1 3 100.0% Function: ~ node:internal/process/esm_loader:1:1 2 3.8% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 2 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 2 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 2 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 2 100.0% Function: ~ node:internal/main/run_main_module:1:1 2 3.8% Function: ~ node:internal/process/esm_loader:1:1 2 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 2 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 2 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 2 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 2 3.8% Function: ~ node:internal/modules/esm/load:1:1 2 100.0% Function: ~ node:internal/modules/esm/loader:1:1 2 100.0% Function: ~ node:internal/process/esm_loader:1:1 2 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 2 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 2 3.8% Function: ~ node:internal/fs/promises:1:1 2 100.0% Function: ~ node:internal/modules/esm/load:1:1 2 100.0% Function: ~ node:internal/modules/esm/loader:1:1 2 100.0% Function: ~ node:internal/process/esm_loader:1:1 2 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 1.9% LazyCompile: ~initializeSourceMapsHandlers node:internal/process/pre_execution:596:38 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 1.9% LazyCompile: ~get BlockList node:net:2228:16 1 100.0% Function: ~ node:internal/modules/esm/fetch_module:1:1 1 100.0% Function: ~ node:internal/modules/esm/get_format:1:1 1 100.0% Function: ~ node:internal/modules/esm/resolve:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 1.9% Function: ~ node:internal/readline/interface:1:1 1 100.0% Function: ~ node:internal/fs/promises:1:1 1 100.0% Function: ~ node:internal/modules/esm/load:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 1.9% Function: ~ node:internal/modules/esm/resolve:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 1.9% Function: ~ node:internal/main/run_main_module:1:1 26 1.8% T _sigprocmask 2 7.7% Function: ^emit node:events:460:44 1 50.0% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 1 100.0% Function: ^emit node:events:460:44 1 100.0% LazyCompile: ~TLSSocket._finishInit node:_tls_wrap:933:43 1 100.0% LazyCompile: ~ssl.onhandshakedone node:_tls_wrap:741:27 1 50.0% LazyCompile: ~ node:net:318:24 1 100.0% LazyCompile: ~done node:_tls_wrap:579:16 1 3.8% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~socketOnData node:_http_client:529:22 1 100.0% Function: ^emit node:events:460:44 1 100.0% LazyCompile: ~addChunk node:internal/streams/readable:312:18 1 100.0% LazyCompile: ~readableAddChunk node:internal/streams/readable:242:26 1 3.8% LazyCompile: ~resolveParams /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-endpoint/dist-cjs/adaptors/getEndpointFromInstructions.js:15:23 1 100.0% LazyCompile: ~getEndpointFromInstructions /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-endpoint/dist-cjs/adaptors/getEndpointFromInstructions.js:6:37 1 100.0% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-endpoint/dist-cjs/endpointMiddleware.js:6:31 1 100.0% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-ssec/dist-cjs/index.js:5:22 1 100.0% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/middleware-sdk-s3/dist-cjs/validate-bucket-name.js:6:22 1 3.8% LazyCompile: ~push node:internal/fixed_queue:99:7 1 100.0% LazyCompile: ~nextTick node:internal/process/task_queues:103:18 1 100.0% LazyCompile: ~TLSSocket node:_tls_wrap:470:19 1 100.0% LazyCompile: ~connect node:_tls_wrap:1612:35 1 100.0% LazyCompile: ~createConnection node:https:118:26 1 3.8% LazyCompile: ~processHeader node:_http_outgoing:570:23 1 100.0% LazyCompile: ~_storeHeader node:_http_outgoing:439:22 1 100.0% LazyCompile: ~_implicitHeader node:_http_client:396:67 1 100.0% LazyCompile: ~end node:_http_outgoing:972:45 1 100.0% LazyCompile: ~writeBody /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/node-http-handler/dist-cjs/write-request-body.js:17:19 1 3.8% LazyCompile: ~parserOnHeadersComplete node:_http_common:72:33 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~socketOnData node:_http_client:529:22 1 100.0% Function: ^emit node:events:460:44 1 100.0% Function: ^addChunk node:internal/streams/readable:312:18 1 3.8% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 1 100.0% Function: ^emit node:events:460:44 1 100.0% LazyCompile: ~TLSSocket._finishInit node:_tls_wrap:933:43 1 100.0% Function: ^ssl.onhandshakedone node:_tls_wrap:741:27 1 3.8% LazyCompile: ~internalConnect node:net:1003:25 1 100.0% Function: ^defaultTriggerAsyncIdScope node:internal/async_hooks:455:36 1 100.0% LazyCompile: ~emitLookup node:net:1293:46 1 100.0% LazyCompile: ~onlookup node:dns:105:18 1 3.8% LazyCompile: ~formatValue node:internal/util/inspect:766:21 1 100.0% LazyCompile: ~inspect node:internal/util/inspect:310:17 1 100.0% LazyCompile: ~formatWithOptionsInternal node:internal/util/inspect:2154:35 1 100.0% LazyCompile: ~formatWithOptions node:internal/util/inspect:2133:27 1 100.0% LazyCompile: ~value node:internal/console/constructor:337:20 1 3.8% LazyCompile: ~finishMaybe node:internal/streams/writable:718:21 1 100.0% LazyCompile: ~Writable.end node:internal/streams/writable:597:34 1 100.0% LazyCompile: ~Socket.end node:net:696:32 1 100.0% LazyCompile: ~endWritableNT node:internal/streams/readable:1381:23 1 100.0% Function: ^processTicksAndRejections node:internal/process/task_queues:67:35 1 3.8% LazyCompile: ~close node:internal/fs/promises:216:11 1 100.0% LazyCompile: ~ node:internal/fs/promises:356:5 1 3.8% Function: ^B node:internal/deps/cjs-module-lexer/dist/lexer:1:824 1 100.0% LazyCompile: ~parse node:internal/deps/cjs-module-lexer/dist/lexer:1:131 1 100.0% LazyCompile: ~cjsPreparseModuleExports node:internal/modules/esm/translators:193:34 1 100.0% LazyCompile: ~ node:internal/modules/esm/translators:232:36 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 3.8% Function: ^ node:internal/validators:419:42 1 100.0% Function: ^internalCompileFunction node:internal/vm:30:33 1 100.0% Function: ^wrapSafe node:internal/modules/cjs/loader:1117:18 1 100.0% Function: ^Module._compile node:internal/modules/cjs/loader:1173:37 1 100.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 17 1.1% T _semaphore_destroy 17 1.1% /usr/lib/system/libsystem_pthread.dylib 2 11.8% LazyCompile: ~value node:internal/console/constructor:337:20 2 100.0% LazyCompile: ~log node:internal/console/constructor:376:6 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 2 100.0% LazyCompile: ~run file:///Users/rvaknin/test_folder/3560a/sample.js:44:19 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.9% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~primordials.SafePromiseAllReturnArrayLike node:internal/per_context/primordials:494:45 1 100.0% LazyCompile: ~import node:internal/modules/esm/loader:509:15 1 100.0% LazyCompile: ~ node:internal/modules/run_main:55:29 1 100.0% LazyCompile: ~loadESM node:internal/process/esm_loader:88:41 1 5.9% LazyCompile: ~toRealPath node:internal/modules/cjs/loader:449:20 1 100.0% LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% LazyCompile: ~resolveMainPath node:internal/modules/run_main:15:25 1 100.0% LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 5.9% LazyCompile: ~setTimeout node:_http_client:930:57 1 100.0% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/node-http-handler/dist-cjs/node-http-handler.js:50:28 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~handle /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/node-http-handler/dist-cjs/node-http-handler.js:46:17 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.9% LazyCompile: ~realpathSync node:fs:2474:22 1 100.0% LazyCompile: ~toRealPath node:internal/modules/cjs/loader:449:20 1 100.0% LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% LazyCompile: ~resolveMainPath node:internal/modules/run_main:15:25 1 100.0% LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31 1 5.9% LazyCompile: ~readFileHandle node:internal/fs/promises:426:30 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.9% LazyCompile: ~patchProcessObject node:internal/process/pre_execution:134:28 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 5.9% LazyCompile: ~defaultResolve node:internal/modules/esm/resolve:1063:30 1 100.0% LazyCompile: ~ObjectDefineProperty.__proto__ node:internal/modules/esm/loader:148:5 1 100.0% LazyCompile: ~resolve node:internal/modules/esm/loader:789:16 1 100.0% LazyCompile: ~getModuleJob node:internal/modules/esm/loader:410:21 1 100.0% LazyCompile: ~import node:internal/modules/esm/loader:509:15 1 5.9% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 100.0% LazyCompile: ~refresh node:internal/util/colors:10:10 1 100.0% Function: ~ node:internal/util/colors:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 5.9% LazyCompile: ~ReadableState node:internal/streams/readable:83:23 1 100.0% LazyCompile: ~Readable node:internal/streams/readable:186:18 1 100.0% LazyCompile: ~Duplex node:internal/streams/duplex:54:16 1 100.0% LazyCompile: ~Socket node:net:336:16 1 100.0% LazyCompile: ~WriteStream node:tty:84:21 1 5.9% LazyCompile: ~Duplex node:internal/streams/duplex:54:16 1 100.0% LazyCompile: ~Socket node:net:336:16 1 100.0% LazyCompile: ~WriteStream node:tty:84:21 1 100.0% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 5.9% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 5.9% Function: ~ node:internal/fs/promises:1:1 1 100.0% Function: ~ node:internal/modules/esm/load:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 ```
V2 Profile ```console Statistical profiling result from isolate-0x130040000-75387-v8.log, (698 ticks, 5 unaccounted, 0 excluded). [Shared libraries]: ticks total nonlib name 17 2.4% /usr/lib/system/libsystem_malloc.dylib 14 2.0% /usr/lib/system/libsystem_pthread.dylib 14 2.0% /usr/lib/system/libsystem_c.dylib 6 0.9% /usr/lib/libc++.1.dylib 3 0.4% /usr/lib/system/libsystem_kernel.dylib 1 0.1% /usr/lib/libc++abi.dylib [JavaScript]: ticks total nonlib name 3 0.4% 0.5% LazyCompile: *normalizeString node:path:66:25 2 0.3% 0.3% LazyCompile: *resolve node:path:1091:10 2 0.3% 0.3% LazyCompile: *Module._findPath node:internal/modules/cjs/loader:555:28 2 0.3% 0.3% Function: ^emit node:events:460:44 2 0.3% 0.3% Function: *wasm-function[15] 1 0.1% 0.2% LazyCompile: *dirname node:path:1275:10 1 0.1% 0.2% LazyCompile: *Module._resolveLookupPaths node:internal/modules/cjs/loader:753:38 1 0.1% 0.2% LazyCompile: *Module._nodeModulePaths node:internal/modules/cjs/loader:715:37 1 0.1% 0.2% LazyCompile: *C node:internal/deps/cjs-module-lexer/dist/lexer:1:1152 1 0.1% 0.2% Function: wasm-function[38] 1 0.1% 0.2% Function: ^trySelf node:internal/modules/cjs/loader:497:17 1 0.1% 0.2% Function: ^popAsyncContext node:internal/async_hooks:553:25 1 0.1% 0.2% Function: ^parseTimestamp /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:343:44 1 0.1% 0.2% Function: ^onwrite node:internal/streams/writable:428:17 1 0.1% 0.2% Function: ^get node:_http_outgoing:173:6 1 0.1% 0.2% Function: ^emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:680:27 1 0.1% 0.2% Function: ^alignPool node:buffer:167:19 1 0.1% 0.2% Function: ^_writeRaw node:_http_outgoing:390:19 1 0.1% 0.2% Function: ^_unrefTimer node:net:484:52 1 0.1% 0.2% Function: ^C node:internal/deps/cjs-module-lexer/dist/lexer:1:1152 1 0.1% 0.2% Function: ^ node:internal/validators:419:42 [C++]: ticks total nonlib name 244 35.0% 37.9% T node::contextify::ContextifyScript::~ContextifyScript() 143 20.5% 22.2% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 121 17.3% 18.8% T _posix_spawnattr_setflags 49 7.0% 7.6% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 18 2.6% 2.8% T _sigprocmask 6 0.9% 0.9% T __kernelrpc_mach_port_move_member_trap 5 0.7% 0.8% T _task_get_exception_ports 4 0.6% 0.6% T ___bsdthread_terminate 3 0.4% 0.5% t ___pfz_setup 3 0.4% 0.5% T _semaphore_destroy 3 0.4% 0.5% T _mach_timebase_info_trap 2 0.3% 0.3% t std::__1::ostreambuf_iterator > std::__1::__pad_and_output >(std::__1::ostreambuf_iterator >, char const*, char const*, char const*, std::__1::ios_base&, char) 2 0.3% 0.3% t std::__1::basic_ostream >& std::__1::__put_character_sequence >(std::__1::basic_ostream >&, char const*, unsigned long) 2 0.3% 0.3% T node::HandleWrap::Close(v8::FunctionCallbackInfo const&) 2 0.3% 0.3% T node::AsyncWrap::EmitTraceEventAfter(node::AsyncWrap::ProviderType, double) 1 0.1% 0.2% t void std::__1::__tree_balance_after_insert*>(std::__1::__tree_node_base*, std::__1::__tree_node_base*) 1 0.1% 0.2% t __os_nospin_lock_lock_slow 1 0.1% 0.2% T _mach_port_insert_right 1 0.1% 0.2% T _mach_port_insert_member [Summary]: ticks total nonlib name 27 3.9% 4.2% JavaScript 611 87.5% 95.0% C++ 7 1.0% 1.1% GC 55 7.9% Shared libraries 5 0.7% Unaccounted [C++ entry points]: ticks cpp total name 226 49.0% 32.4% T node::contextify::ContextifyScript::~ContextifyScript() 143 31.0% 20.5% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 49 10.6% 7.0% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 15 3.3% 2.1% T _sigprocmask 8 1.7% 1.1% T node::loader::ModuleWrap::Evaluate(v8::FunctionCallbackInfo const&) 6 1.3% 0.9% T __kernelrpc_mach_port_move_member_trap 5 1.1% 0.7% T _task_get_exception_ports 3 0.7% 0.4% t ___pfz_setup 2 0.4% 0.3% t std::__1::ostreambuf_iterator > std::__1::__pad_and_output >(std::__1::ostreambuf_iterator >, char const*, char const*, char const*, std::__1::ios_base&, char) 2 0.4% 0.3% T node::HandleWrap::Close(v8::FunctionCallbackInfo const&) 1 0.2% 0.1% t void std::__1::__tree_balance_after_insert*>(std::__1::__tree_node_base*, std::__1::__tree_node_base*) 1 0.2% 0.1% t std::__1::basic_ostream >& std::__1::__put_character_sequence >(std::__1::basic_ostream >&, char const*, unsigned long) [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. Callers occupying less than 1.0% are not shown. ticks parent name 244 35.0% T node::contextify::ContextifyScript::~ContextifyScript() 24 9.8% Function: ^TLSSocket.getPeerCertificate node:_tls_wrap:999:50 20 83.3% Function: ^onConnectSecure node:_tls_wrap:1531:25 20 100.0% Function: ^emit node:events:460:44 20 100.0% Function: ^emit node:domain:478:44 20 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 4 16.7% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 4 100.0% Function: ^emit node:events:460:44 4 100.0% Function: ^emit node:domain:478:44 4 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 21 8.6% Function: ^openSync node:fs:591:18 21 100.0% Function: ^readFileSync node:fs:465:22 18 85.7% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 18 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 18 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 9.5% Function: ^cjsPreparseModuleExports node:internal/modules/esm/translators:193:34 2 100.0% Function: ^ node:internal/modules/esm/translators:232:36 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 4.8% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% LazyCompile: ~Module._load node:internal/modules/cjs/loader:851:24 14 5.7% LazyCompile: ~configSecureContext node:internal/tls/secure-context:124:29 13 92.9% LazyCompile: ~createSecureContext node:_tls_common:99:29 13 100.0% LazyCompile: ~connect node:_tls_wrap:1612:35 13 100.0% LazyCompile: ~createConnection node:https:118:26 13 100.0% LazyCompile: ~createSocket node:_http_agent:319:53 1 7.1% Function: ^createSecureContext node:_tls_common:99:29 1 100.0% Function: ^connect node:_tls_wrap:1612:35 1 100.0% Function: ^createConnection node:https:118:26 1 100.0% Function: ^createSocket node:_http_agent:319:53 13 5.3% T node::contextify::ContextifyScript::~ContextifyScript() 3 23.1% T node::contextify::ContextifyScript::~ContextifyScript() 1 33.3% Function: ^stat node:internal/modules/cjs/loader:161:14 1 100.0% Function: ^tryFile node:internal/modules/cjs/loader:440:17 1 100.0% Function: ^tryExtensions node:internal/modules/cjs/loader:456:23 1 33.3% Function: ^readPackage node:internal/modules/cjs/loader:335:21 1 100.0% Function: ^readPackageScope node:internal/modules/cjs/loader:377:26 1 100.0% Function: ^trySelf node:internal/modules/cjs/loader:497:17 1 33.3% Function: ^ /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:113:37 1 100.0% LazyCompile: *each /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:517:22 1 100.0% Function: ^extractData /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:100:21 2 15.4% LazyCompile: *readPackageScope node:internal/modules/cjs/loader:377:26 1 50.0% Function: ^trySelf node:internal/modules/cjs/loader:497:17 1 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 50.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 15.4% Function: ^Module._findPath node:internal/modules/cjs/loader:555:28 2 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 2 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 7.7% LazyCompile: ~isIPv6 node:internal/net:38:16 1 100.0% LazyCompile: ~isIP node:internal/net:45:14 1 100.0% LazyCompile: ~lookupAndConnect node:net:1202:26 1 100.0% LazyCompile: ~Socket.connect node:net:1134:36 1 7.7% LazyCompile: ~generateURI /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:8:21 1 100.0% LazyCompile: ~populateURI /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:62:21 1 100.0% LazyCompile: ~buildRequest /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:90:22 1 100.0% LazyCompile: ~buildRequest /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest_xml.js:28:22 1 7.7% LazyCompile: ~checkIsHttpToken node:_http_common:210:26 1 100.0% LazyCompile: ~ node:_http_outgoing:631:44 1 100.0% LazyCompile: ~setHeader node:_http_outgoing:661:57 1 100.0% LazyCompile: ~ClientRequest node:_http_client:134:23 1 7.7% Function: ^readPackage node:internal/modules/cjs/loader:335:21 1 100.0% Function: ^readPackageScope node:internal/modules/cjs/loader:377:26 1 100.0% Function: ^trySelf node:internal/modules/cjs/loader:497:17 1 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 1 7.7% Function: ^getOwn node:internal/bootstrap/loaders:188:16 1 100.0% Function: ^syncExports node:internal/bootstrap/loaders:307:14 1 100.0% LazyCompile: ~ node:internal/bootstrap/loaders:293:15 1 100.0% T node::loader::ModuleWrap::Evaluate(v8::FunctionCallbackInfo const&) 1 7.7% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 100.0% Function: ^require node:internal/modules/cjs/helpers:102:31 6 2.5% LazyCompile: ~TLSSocket.getPeerCertificate node:_tls_wrap:999:50 6 100.0% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 6 100.0% Function: ^emit node:events:460:44 6 100.0% Function: ^emit node:domain:478:44 6 100.0% LazyCompile: ~TLSSocket._finishInit node:_tls_wrap:933:43 5 2.0% LazyCompile: ~done node:_tls_wrap:579:16 5 2.0% Function: ^handleWriteReq node:internal/stream_base_commons:45:24 5 100.0% Function: ^writeGeneric node:internal/stream_base_commons:147:22 5 100.0% Function: ^Socket._writeGeneric node:net:897:42 5 100.0% Function: ^Socket._write node:net:934:35 5 100.0% Function: ^doWrite node:internal/streams/writable:401:17 5 2.0% Function: ^closeSync node:fs:541:19 5 100.0% Function: ^readFileSync node:fs:465:22 3 60.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 3 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 3 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 2 40.0% Function: ^cjsPreparseModuleExports node:internal/modules/esm/translators:193:34 2 100.0% Function: ^ node:internal/modules/esm/translators:232:36 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 4 1.6% Function: ^socketMethodProxy node:_tls_wrap:1030:36 3 75.0% Function: ^onConnectSecure node:_tls_wrap:1531:25 3 100.0% Function: ^emit node:events:460:44 3 100.0% Function: ^emit node:domain:478:44 3 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 1 25.0% LazyCompile: ~onConnectSecure node:_tls_wrap:1531:25 1 100.0% Function: ^emit node:events:460:44 1 100.0% Function: ^emit node:domain:478:44 1 100.0% Function: ^TLSSocket._finishInit node:_tls_wrap:933:43 4 1.6% Function: ^TLSSocket._start node:_tls_wrap:962:38 4 100.0% Function: ^onceWrapper node:events:622:21 4 100.0% Function: ^emit node:events:460:44 4 100.0% Function: ^emit node:domain:478:44 2 50.0% LazyCompile: ~afterConnect node:net:1440:22 2 50.0% Function: ^afterConnect node:net:1440:22 3 1.2% LazyCompile: *readPackageScope node:internal/modules/cjs/loader:377:26 3 100.0% Function: ^trySelf node:internal/modules/cjs/loader:497:17 3 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 3 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 3 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 3 1.2% Function: ^readPackage node:internal/modules/cjs/loader:335:21 2 66.7% Function: ^resolveExports node:internal/modules/cjs/loader:528:24 2 100.0% Function: ^Module._findPath node:internal/modules/cjs/loader:555:28 2 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 2 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 33.3% LazyCompile: *Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% Function: ^Module._resolveFilename node:internal/modules/cjs/loader:948:35 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 143 20.5% T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo const&) 141 98.6% Function: ^internalCompileFunction node:internal/vm:30:33 139 98.6% Function: ^wrapSafe node:internal/modules/cjs/loader:1117:18 139 100.0% Function: ^Module._compile node:internal/modules/cjs/loader:1173:37 122 87.8% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 122 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 17 12.2% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 17 100.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 2 1.4% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 2 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 2 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 50.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 1 50.0% Function: ^Module.load node:internal/modules/cjs/loader:1069:33 2 1.4% LazyCompile: ~internalCompileFunction node:internal/vm:30:33 2 100.0% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 2 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 2 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 2 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 121 17.3% T _posix_spawnattr_setflags 49 7.0% T node::builtins::BuiltinLoader::CompileFunction(v8::FunctionCallbackInfo const&) 31 63.3% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 27 87.1% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 5 18.5% Function: ~ node:https:1:1 5 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 5 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 5 18.5% Function: ~ node:http2:1:1 5 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 5 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 2 7.4% Function: ~ node:tls:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.4% Function: ~ node:internal/http2/core:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 2 7.4% Function: ~ node:child_process:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 2 7.4% Function: ~ node:assert:1:1 2 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 2 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.7% LazyCompile: ~lazyWebCrypto node:crypto:125:23 1 100.0% LazyCompile: ~get node:crypto:369:8 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 3.7% LazyCompile: ~lazyLoadStreams node:fs:2907:25 1 100.0% LazyCompile: ~get ReadStream node:fs:3050:17 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 3.7% LazyCompile: ~initCJSParse node:internal/modules/esm/translators:58:28 1 100.0% LazyCompile: ~commonjsStrategy node:internal/modules/esm/translators:147:60 1 100.0% LazyCompile: ~moduleProvider node:internal/modules/esm/loader:452:28 1 3.7% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 100.0% LazyCompile: ~refresh node:internal/util/colors:10:10 1 3.7% Function: ~ node:internal/http2/compat:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.7% Function: ~ node:internal/child_process:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.7% Function: ~ node:_tls_common:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.7% Function: ~ node:_http_server:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 3.7% Function: ~ node:_http_common:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 3 9.7% LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25 3 100.0% Function: ^loadBuiltinModule node:internal/modules/cjs/helpers:45:27 3 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 3 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 3.2% Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25 1 100.0% Function: ^loadBuiltinModule node:internal/modules/cjs/helpers:45:27 1 100.0% Function: ^Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 3 6.1% Function: ~ node:internal/modules/esm/fetch_module:1:1 3 100.0% Function: ~ node:internal/modules/esm/get_format:1:1 3 100.0% Function: ~ node:internal/modules/esm/resolve:1:1 3 100.0% Function: ~ node:internal/modules/esm/loader:1:1 3 100.0% Function: ~ node:internal/process/esm_loader:1:1 3 6.1% Function: ~ node:internal/fs/promises:1:1 3 100.0% Function: ~ node:internal/modules/esm/load:1:1 3 100.0% Function: ~ node:internal/modules/esm/loader:1:1 3 100.0% Function: ~ node:internal/process/esm_loader:1:1 3 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 2 4.1% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 2 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 2 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 2 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 2 100.0% Function: ~ node:internal/main/run_main_module:1:1 2 4.1% Function: ~ node:internal/process/esm_loader:1:1 2 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 2 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 2 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 2 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 2.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 2.0% LazyCompile: ~initializeSourceMapsHandlers node:internal/process/pre_execution:596:38 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 2.0% Function: ~ node:internal/source_map/source_map_cache:1:1 1 100.0% LazyCompile: ~initializeSourceMapsHandlers node:internal/process/pre_execution:596:38 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 2.0% Function: ~ node:internal/modules/esm/resolve:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 2.0% Function: ~ node:internal/modules/esm/module_map:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 2.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 1 2.0% Function: ~ node:internal/modules/esm/load:1:1 1 100.0% Function: ~ node:internal/modules/esm/loader:1:1 1 100.0% Function: ~ node:internal/process/esm_loader:1:1 1 100.0% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 2.0% Function: ~ node:internal/main/run_main_module:1:1 18 2.6% T _sigprocmask 1 5.6% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% Function: ^getOwn node:internal/bootstrap/loaders:188:16 1 100.0% Function: ^syncExports node:internal/bootstrap/loaders:307:14 1 100.0% LazyCompile: ~ node:internal/bootstrap/loaders:293:15 1 100.0% T node::loader::ModuleWrap::Evaluate(v8::FunctionCallbackInfo const&) 1 5.6% LazyCompile: ~writeBody /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:115:32 1 100.0% Function: ^handleRequest /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:12:40 1 100.0% Function: ^executeSend /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/event_listeners.js:448:27 1 100.0% Function: ^SEND /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/event_listeners.js:366:43 1 100.0% Function: ^callListeners /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:85:40 1 5.6% LazyCompile: ~readFileHandle node:internal/fs/promises:426:30 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.6% LazyCompile: ~patchProcessObject node:internal/process/pre_execution:134:28 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 5.6% LazyCompile: ~hash /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:176:32 1 100.0% LazyCompile: ~stringToSign /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:108:38 1 100.0% LazyCompile: ~signature /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:97:32 1 100.0% LazyCompile: ~authorization /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:87:40 1 100.0% LazyCompile: ~addAuthorization /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:25:46 1 5.6% LazyCompile: ~createSecureContext node:_tls_common:99:29 1 100.0% LazyCompile: ~connect node:_tls_wrap:1612:35 1 100.0% LazyCompile: ~createConnection node:https:118:26 1 100.0% LazyCompile: ~createSocket node:_http_agent:319:53 1 100.0% LazyCompile: ~addRequest node:_http_agent:248:49 1 5.6% LazyCompile: ~channel node:diagnostics_channel:97:17 1 100.0% Function: ~ node:_http_server:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 100.0% Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24 1 100.0% Function: ~ node:https:1:1 1 5.6% LazyCompile: ~basename node:path:1306:11 1 100.0% LazyCompile: ~findLongestRegisteredExtension node:internal/modules/cjs/loader:469:40 1 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% LazyCompile: ~Module._load node:internal/modules/cjs/loader:851:24 1 100.0% LazyCompile: ~Module.require node:internal/modules/cjs/loader:1097:36 1 5.6% LazyCompile: ~_storeHeader node:_http_outgoing:439:22 1 100.0% Function: ^_implicitHeader node:_http_client:396:67 1 100.0% LazyCompile: ~end node:_http_outgoing:972:45 1 100.0% LazyCompile: ~writeBody /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:115:32 1 100.0% Function: ^handleRequest /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:12:40 1 5.6% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:782:35 1 100.0% Function: ^callListeners /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:85:40 1 100.0% Function: ^emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:74:22 1 100.0% Function: ^emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:680:27 1 100.0% Function: ^transition /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:18:28 1 5.6% Function: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/client-s3/dist-cjs/index.js:1:1 1 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 1 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 1 100.0% LazyCompile: ~Module._load node:internal/modules/cjs/loader:851:24 1 5.6% Function: ^onceWrapper node:events:622:21 1 100.0% Function: ^emit node:events:460:44 1 100.0% Function: ^emit node:domain:478:44 1 100.0% LazyCompile: ~ node:net:318:24 1 100.0% LazyCompile: ~done node:_tls_wrap:579:16 1 5.6% Function: ^_implicitHeader node:_http_client:396:67 1 100.0% Function: ^end node:_http_outgoing:972:45 1 100.0% Function: ^writeBody /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:115:32 1 100.0% Function: ^handleRequest /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http/node.js:12:40 1 100.0% Function: ^executeSend /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/event_listeners.js:448:27 1 5.6% Function: ^B node:internal/deps/cjs-module-lexer/dist/lexer:1:824 1 100.0% LazyCompile: ~parse node:internal/deps/cjs-module-lexer/dist/lexer:1:131 1 100.0% LazyCompile: ~cjsPreparseModuleExports node:internal/modules/esm/translators:193:34 1 100.0% LazyCompile: ~ node:internal/modules/esm/translators:232:36 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.6% Function: ^ node:internal/validators:419:42 1 100.0% Function: ^internalCompileFunction node:internal/vm:30:33 1 100.0% Function: ^wrapSafe node:internal/modules/cjs/loader:1117:18 1 100.0% Function: ^Module._compile node:internal/modules/cjs/loader:1173:37 1 100.0% Function: ^Module._extensions..js node:internal/modules/cjs/loader:1227:37 17 2.4% /usr/lib/system/libsystem_malloc.dylib 1 5.9% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% LazyCompile: ~resolvePackageTargetString node:internal/modules/esm/resolve:412:36 1 100.0% LazyCompile: ~resolvePackageTarget node:internal/modules/esm/resolve:519:30 1 100.0% LazyCompile: ~resolvePackageTarget node:internal/modules/esm/resolve:519:30 1 100.0% LazyCompile: ~packageExportsResolve node:internal/modules/esm/resolve:625:31 1 5.9% LazyCompile: ~internalCompileFunction node:internal/vm:30:33 1 100.0% LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1117:18 1 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 1 100.0% LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1227:37 1 100.0% LazyCompile: ~Module.load node:internal/modules/cjs/loader:1069:33 1 5.9% LazyCompile: ~callListeners /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:85:40 1 100.0% LazyCompile: ~emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:74:22 1 100.0% LazyCompile: ~emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:680:27 1 100.0% LazyCompile: ~transition /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:18:28 1 100.0% LazyCompile: ~runTo /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/state_machine.js:6:54 1 5.9% LazyCompile: ~ObjectDefineProperty.__proto__ node:internal/modules/esm/loader:148:5 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 5.9% LazyCompile: ~Module._load node:internal/modules/cjs/loader:851:24 1 100.0% Function: ^Module.require node:internal/modules/cjs/loader:1097:36 1 100.0% Function: ^require node:internal/modules/cjs/helpers:102:31 1 100.0% Function: ~ /Users/rvaknin/test_folder/3560a/node_modules/@aws-sdk/smithy-client/dist-cjs/index.js:1:1 1 100.0% LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1173:37 14 2.0% /usr/lib/system/libsystem_pthread.dylib 1 7.1% LazyCompile: ~toRealPath node:internal/modules/cjs/loader:449:20 1 100.0% LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% LazyCompile: ~resolveMainPath node:internal/modules/run_main:15:25 1 100.0% LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 7.1% LazyCompile: ~setupTraceCategoryState node:internal/process/pre_execution:382:33 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 7.1% LazyCompile: ~realpathSync node:fs:2474:22 1 100.0% LazyCompile: ~toRealPath node:internal/modules/cjs/loader:449:20 1 100.0% LazyCompile: ~Module._findPath node:internal/modules/cjs/loader:555:28 1 100.0% LazyCompile: ~resolveMainPath node:internal/modules/run_main:15:25 1 100.0% LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31 1 7.1% LazyCompile: ~onParseError node:internal/url:564:22 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% Function: ^URL node:internal/url:637:14 1 100.0% LazyCompile: ~defaultResolve node:internal/modules/esm/resolve:1063:30 1 100.0% LazyCompile: ~ObjectDefineProperty.__proto__ node:internal/modules/esm/loader:148:5 1 7.1% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 100.0% LazyCompile: ~refresh node:internal/util/colors:10:10 1 100.0% Function: ~ node:internal/util/colors:1:1 1 100.0% Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27 1 7.1% LazyCompile: ~createHmac node:crypto:164:20 1 100.0% LazyCompile: ~hmac /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:431:24 1 100.0% LazyCompile: ~getSigningKey /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4_credentials.js:54:40 1 100.0% LazyCompile: ~signature /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:97:32 1 100.0% LazyCompile: ~authorization /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:87:40 1 7.1% LazyCompile: ~TLSSocket._init node:_tls_wrap:685:37 1 100.0% Function: ^TLSSocket node:_tls_wrap:470:19 1 100.0% Function: ^connect node:_tls_wrap:1612:35 1 100.0% Function: ^createConnection node:https:118:26 1 100.0% Function: ^createSocket node:_http_agent:319:53 1 7.1% LazyCompile: ~Duplex node:internal/streams/duplex:54:16 1 100.0% LazyCompile: ~Socket node:net:336:16 1 100.0% LazyCompile: ~WriteStream node:tty:84:21 1 100.0% LazyCompile: ~createWritableStdioStream node:internal/bootstrap/switches/is_main_thread:45:35 1 100.0% LazyCompile: ~getStderr node:internal/bootstrap/switches/is_main_thread:168:19 1 7.1% LazyCompile: ~ node:internal/validators:247:3 1 100.0% LazyCompile: ~SocketAddress node:internal/socketaddress:47:14 1 100.0% LazyCompile: ~addAddress node:internal/blocklist:60:13 1 100.0% Function: ~ node:internal/modules/esm/fetch_module:1:1 1 100.0% Function: ~ node:internal/modules/esm/get_format:1:1 1 7.1% LazyCompile: ~ node:_http_client:950:34 1 100.0% Function: ^onceWrapper node:events:622:21 1 100.0% Function: ^emit node:events:460:44 1 100.0% Function: ^emit node:domain:478:44 1 100.0% LazyCompile: ~afterConnect node:net:1440:22 1 7.1% Function: ^emit node:domain:478:44 14 2.0% /usr/lib/system/libsystem_c.dylib 2 14.3% LazyCompile: ~value node:internal/console/constructor:346:20 2 100.0% LazyCompile: ~warn node:internal/console/constructor:381:7 2 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 2 100.0% LazyCompile: ~writeOut node:internal/process/warning:56:18 2 100.0% LazyCompile: ~onWarning node:internal/process/warning:92:19 1 7.1% LazyCompile: ~readPackageScope node:internal/modules/cjs/loader:377:26 1 100.0% LazyCompile: ~shouldUseESMLoader node:internal/modules/run_main:30:28 1 100.0% LazyCompile: ~executeUserEntryPoint node:internal/modules/run_main:74:31 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 7.1% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 7.1% LazyCompile: ~patchProcessObject node:internal/process/pre_execution:134:28 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 100.0% Function: ~ node:internal/main/run_main_module:1:1 1 7.1% LazyCompile: ~parse node:url:175:37 1 100.0% LazyCompile: ~urlParse node:url:143:18 1 100.0% LazyCompile: ~urlParse /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:59:30 1 100.0% LazyCompile: ~Endpoint /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/http.js:43:33 1 100.0% LazyCompile: ~setEndpoint /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/service.js:668:36 1 7.1% LazyCompile: ~getStdout node:internal/bootstrap/switches/is_main_thread:146:19 1 100.0% T node::contextify::ContextifyScript::~ContextifyScript() 1 100.0% Function: ^getOwn node:internal/bootstrap/loaders:188:16 1 100.0% Function: ^syncExports node:internal/bootstrap/loaders:307:14 1 100.0% LazyCompile: ~ node:internal/bootstrap/loaders:293:15 1 7.1% LazyCompile: ~SET_CONTENT_LENGTH /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/event_listeners.js:219:72 1 100.0% LazyCompile: ~callListeners /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:85:40 1 100.0% LazyCompile: ~emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:74:22 1 100.0% LazyCompile: ~emit /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:680:27 1 100.0% LazyCompile: ~transition /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/request.js:18:28 1 7.1% LazyCompile: ~ReadableState node:internal/streams/readable:83:23 1 100.0% LazyCompile: ~Readable node:internal/streams/readable:186:18 1 100.0% LazyCompile: ~Duplex node:internal/streams/duplex:54:16 1 100.0% LazyCompile: ~Socket node:net:336:16 1 100.0% LazyCompile: ~WriteStream node:tty:84:21 1 7.1% LazyCompile: ~ /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:113:37 1 100.0% LazyCompile: *each /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:517:22 1 100.0% LazyCompile: ~extractData /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest.js:100:21 1 100.0% LazyCompile: ~extractData /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/protocol/rest_xml.js:65:21 1 100.0% Function: ^callListeners /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/sequential_executor.js:85:40 1 7.1% Function: ~ node:internal/modules/cjs/loader:1:1 1 100.0% LazyCompile: ~initializeCJSLoader node:internal/process/pre_execution:557:29 1 100.0% LazyCompile: ~setupUserModules node:internal/process/pre_execution:120:26 1 100.0% LazyCompile: ~prepareExecution node:internal/process/pre_execution:51:26 1 100.0% LazyCompile: ~prepareMainThreadExecution node:internal/process/pre_execution:35:36 1 7.1% Function: ^processTicksAndRejections node:internal/process/task_queues:67:35 1 7.1% Function: ^iso8601 /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/util.js:295:30 1 100.0% Function: ^addAuthorization /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/signers/v4.js:25:46 1 100.0% Function: ^ /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/event_listeners.js:307:48 1 100.0% Function: ^finish /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/config.js:395:20 1 100.0% Function: ^ /Users/rvaknin/test_folder/3560a/node_modules/aws-sdk/lib/config.js:408:36 ```

Github repo to reproduce issue

ToyboxZach commented 1 year ago

We are seeing a similar problem and I don't think this is much of an edge case.

We are pretty much just piping the files from s3 to the client

 const commandResult = await client.send(command);
 commandResult.Body.pipe(response);

And if there is a file that takes like a minute to download (slower devices/slower internet) If you download more an more from the server on different clients we see the download go slower and slower until it stops, this is even with the work around.

I may be misunderstanding how to do this, but a similar flow worked great from v2.

kuhe commented 1 year ago

https://github.com/aws/aws-sdk-js-v3/issues/3560#issuecomment-1484140333 the https.Agent configuration above is not exactly a workaround, it is the correct and recommended way to increase the socket pool.

I will submit a change that begins the socket timeout countdown before the socket event as requested in https://github.com/aws/aws-sdk-js-v3/issues/3722 that may be related to @ToyboxZach 's problem.

randomhash commented 1 year ago

@kuhe @RanVaknin Workaround not working for the parallel getObject + upload requests, after around 100 items fetched/uploaded connection hangs concurrency 20-50 S3 client initialized on lambda start Basically works once every ~20 times correctly

Single client for both download and upload not really working

the only option that somehow works consistently is to create 2 separate clients for the actual upload and download:

import {NodeHttpHandler} from '@smithy/node-http-handler';
import {Agent} from 'node:https';

const s3download = new S3({
  region: process.env.AWS_REGION,
  logger: console,
  forcePathStyle: true,
  requestHandler: new NodeHttpHandler({
    httpsAgent: new Agent({
      timeout: 5000,
      maxSockets: 1000, // default 50
      // keepAlive is a default from AWS SDK. We want to preserve this for
      // performance reasons.
      keepAlive: true,
      keepAliveMsecs: 1000, // default unset,
    }),
    connectionTimeout: 1000,
    requestTimeout: 5000, // default 0
  }),
});

const s3upload = new S3({
  region: process.env.AWS_REGION,
  logger: console,
  forcePathStyle: true,
  requestHandler: new NodeHttpHandler({
    httpsAgent: new Agent({
      maxSockets: 1000, // default 50
      keepAlive: false,
    }),
    connectionTimeout: 1000,
    requestTimeout: 5000, // default 0
  }),
});

And im kinda sure that this will also fail if enough files are supplied

1nstinct commented 10 months ago

Any updates on this issue? We are experiencing the issue on our side too. Comparing V2 request breakdown and V3 request breakdown side by side made by the datadog tracer. Made all suggestions about sockets from above. To explain the images below: V3 requests consists of the weird HTTP EC2META requests plus the actual S3 request. V2 has only the actual S3 request.

V2

Screenshot 2024-01-10 at 6 22 49 PM

V3

Screenshot 2024-01-10 at 6 19 15 PM
kuhe commented 10 months ago

@1nstinct you provided a flame graph, but you should provide a minimal reproduction with code. Are you instantiating a client per request?

1nstinct commented 10 months ago

@kuhe yes, every request I instantiating a new client and destroying it after.

function read() {
  return [
    (req, res, next) => {
      const modelId = 'model_id';
      const model = req.params[modelId];
      const client = new AWS.S3({
        "region": "us-west-2",
        "useAccelerateEndpoint": true,
        "signatureVersion": "v4"
      });
      const begin = Date.now();

      req.s3Params = {
        Bucket: model.bucket,
        Key: `${model.key}/${req.params[0]}`,
        ResponseContentType: "application/octet-stream",
      };

      client.getObject(req.s3Params)
        .createReadStream()
        .on('error', err => {
          if (err.statusCode === 404) {
            return next(boom.notFound());
          }
          // TODO: Better error handling
          next(err);
        })
        .on('end', () => {
          // eslint-disable-next-line
          if (DEBUG) console.log(`============== V2 file ${req.params[0]} download time: ${Date.now() - begin} ms`);
        })
        .pipe(res);
    }
  ];
}
function readV3() {
  return [
    async (req, res, next) => {
      try {
        const modelId = 'model_id';
        const model = req.params[modelId];
        let instanceCredentials;
        if (process.env.NODE_ENV === 'localhost') {
          instanceCredentials = fromIni({
            maxRetries: 5, // The maximum number of times any HTTP connections should be retried
            timeout: 100, // The connection timeout (in milliseconds) to apply to any remote requests
          });
        } else {
          instanceCredentials = fromInstanceMetadata({
            maxRetries: 5, // The maximum number of times any HTTP connections should be retried
            timeout: 100, // The connection timeout (in milliseconds) to apply to any remote requests
          });
        }
        const serviceConfig = {
          region: "us-west-2",
          useAccelerateEndpoint: true,
          // Use a custom request handler so that we can adjust the HTTPS Agent and
          // socket behavior.
          requestHandler: new NodeHttpHandler({
            httpsAgent: new https.Agent({
              maxSockets: 500, // avoid hanging because of all sockets are in use

              // keepAlive is a default from AWS SDK. We want to preserve this for
              // performance reasons.
              keepAlive: true,
              keepAliveMsecs: 1000,
            }),
            socketTimeout: 5000,
          }),
          credentials: instanceCredentials
        };
        const begin = Date.now();
        req.s3Params = {
          Bucket: model.bucket,
          Key: `${model.key}/${req.params[0]}`,
          ResponseContentType: "application/octet-stream",
        };
        const command = new GetObjectCommand(req.s3Params);

        // new client per request
        const client = new S3Client(serviceConfig);
        const response = await client.send(command);

        res.status(response.Body.statusCode);
        response.Body.on('end', () => {
          client.destroy();
          // eslint-disable-next-line
          if (DEBUG) console.log(`============== V3 file ${req.params[0]} download time: ${Date.now() - begin} ms`);
        });
        response.Body.pipe(res);
      } catch (err) {
        if (err.name === 'NoSuchKey') {
          return next(boom.notFound());
        }
        // TODO: Better error handling
        return next(boom.badRequest(err.message));
      }
    }
  ];
}
"dependencies": {
    "@aws-sdk/client-s3": "^3.485.0",
    "@aws-sdk/credential-providers": "^3.485.0",
    "@aws-sdk/node-http-handler": "^3.374.0",
  }

node -v v18.16.1

A single file download speed results. No multi thread downloads. image

kuhe commented 10 months ago

Avoid instantiating the client every request. Doing so causes the credentials to be fetched, in this case from ec2 metadata service.

1nstinct commented 10 months ago

@kuhe the performance for V3 is close to V2 now. But we can't use this solution because we started getting "socket hang up" error I believe because V3 client is global variable now - we do not initialize it every request.

looks like it's similar to what this guy reported https://github.com/aws/aws-sdk-js-v3/issues/5561#issuecomment-1850924931

image

I tried to used these socket configs:

{
      "region": "us-west-2",
      "maxSockets": 5000,
      "keepAliveMsecs": 5000,
      "socketTimeout": 120000,
      "useAccelerateEndpoint": true
    }
{
      "region": "us-west-2",
      "maxSockets": 500,
      "keepAliveMsecs": 1000,
      "socketTimeout": 5000,
      "useAccelerateEndpoint": true
    }

with every config we are getting the error.

KernelDeimos commented 10 months ago

I found this issue via a comment on this StackOverflow post, although as far as I can tell the issues are slightly different: https://stackoverflow.com/questions/73256172/nodejs-amazon-aws-sdk-s3-client-stops-working-intermittently

Should I open a new issue for this? I'm not the OP of the SO post, but I've noticed an issue as described there so I wonder if somebody with more insight can tell me if it's related. Every few days, an instance of S3Client just stops working - calling await client.send(new GetObjectCommand({ ... })) does not throw an exception and does not return; it hangs indefinitely. It took me a while to narrow the issue down to this cause.

Edit I found this issue which seems to indicate that yes, it is related.

summera commented 10 months ago

Been tracking this ticket and just wanted to throw in our experience. We have a node service running in Fargate on ECS that essentially acts as a proxy to images in S3 buckets. It works with streams, reading from the S3 bucket, applying some image transformations and returning the transformed images by writing to a stream (an ExpressJS response). It handles many concurrent requests.

We attempted an upgrade to the AWS SDK v3 and saw a memory leak as well as hanging responses. We'd see the node process completely get hung up and be non-responsive. Log output would would stop and it would then be terminated due to failed health checks since it couldn't respond.

Everything works perfectly fine with the v2 SDK, so we had to revert. It's worth noting that when using the v3 SDK the issues didn't show up immediately, it would take a few days or more before we'd have a task get hung up and terminated due to being non-responsive. We are only creating one instance of the client. https://github.com/aws/aws-sdk-js-v3/issues/4596 seems to be related to the issues discussed here and some are saying that the config in https://github.com/aws/aws-sdk-js-v3/issues/3560#issuecomment-1484140333 fixes the issue for them.

When upgrading to v3 do we still need to apply the changes from https://github.com/aws/aws-sdk-js-v3/issues/3560#issuecomment-1484140333 or should it be fine without it? If so, any idea why this would be required in v3 and was not in v2?

kuhe commented 10 months ago

We are theorizing here without more specific reproduction examples, but one thing to keep in mind is that in the v2 SDK, the S3 objects are buffered by default when you request them (reading the stream).

In v3, the S3::getObject request only opens a stream. You must consume the stream or garbage collect the client or its request handler to keep the connections open to new traffic. One example, reading the stream into a string:

// v2
const get = await s3.getObject({ ... }).promise(); // this buffers (consumes) the stream already.
// v3
const get = await s3.getObject({ ... }); // object .Body has unconsumed stream.
const str = await get.Body.transformToString(); // consumes the stream.
1nstinct commented 10 months ago

So I managed to fix all my issues.

  1. Socket hang up happens when I use the same client for all the requests. It was not enough amount of sockets to maintain so many simultaneous requests. So I am creating a new client and generating a new set of credentials for it every request
  2. I am not using fromInstanceMetadata() to get creds or anything like that because IMDS is too slow and it is slowing down the entire process. Instead I am getting creds from AssumeRoleCommand, saving them as env vars and consuming them through fromEnv(). I set up a cronjob or a simple setInterval to refresh creds because of AssumeRole session that is tend to expire.

Now V2 and V3 performance is similar

rijkvanzanten commented 10 months ago

The solution provided in here https://github.com/aws/aws-sdk-js-v3/issues/3560#issuecomment-1484140333 has worked great for us. I'm a little hazy on the details (it's been a minute), but IIRC it effectively "reverts" the v3 http agent settings back to aws-sdk v2's settings, which solved the problems for us:

import { S3Client } from "@aws-sdk/client-s3";
import { NodeHttpHandler } from "@smithy/node-http-handler";
import { Agent as HttpAgent } from "node:http";
import { Agent as HttpsAgent } from "node:https";

const connectionTimeout = 5000;
const socketTimeout = 120000;
const maxSockets = 500;
const keepAlive = true;

const client = new S3Client({
    requestHandler: new NodeHttpHandler({
        connectionTimeout,
        socketTimeout,
        httpAgent: new HttpAgent({ maxSockets, keepAlive }),
        httpsAgent: new HttpsAgent({ maxSockets, keepAlive }),
    }),
});

Our problem was that bad requests/operations would never timeout, which combined with the the low default maxSockets meant at a certain point all sockets were in use for requests that were long timed out / dead, which in turn made our endpoints "hang" and be unresponsive.

clakech commented 9 months ago

👋

When downloading hundreds of files from s3 using v3 SDK we experience this issue on lambda which stops SILENTLY working after around 150 files most of the time. Sometimes it works, it depends on the gods of the network.

There are no warning or error logs, even inside the SDK when providing a logger. So we investigate for quite a long time before finding this issue and the possible workarounds.

Is it possible to have a log or an event or something to know when the SDK is stuck because of lack of available sockets?

I don't think that downloading 200 files to transform them using streams is an edge case and this issue deserves an improvement they would help troubleshooting the issue without reading hundreds of web pages on SO or GitHub.

jan-osch commented 8 months ago

@clakech did you try using higher values for maxSockets? @rijkvanzanten socketTimeout is actually deprecated, you should use requestTimeout instead

cduyzh commented 7 months ago

Summary of AWS Lambda Challenges and Optimizations

Issue Encountered:

When using AWS Lambda, the "GetObjectCommand" is utilized to handle the same problem in AWS Lambda. When a client sends a request, an error message may occur:

WARN @smithy/node-http-handler:WARN socket usage at capacity=50 and 131 (any number over 50) additional requests are enqueued. See Node Configuring MaxSockets or increase socketAcquisitionWarningTimeout=(millis) in the NodeHttpHandler config.

Implementation Details:

I employed Lambda to automate the process of handling image uploads to S3 bucket A. The process involves listening to events in bucket A and triggering Lambda functions. The main steps in the Lambda function implementation are as follows:

  1. Obtain the image and metadata using the "GetObjectCommand".
  2. Compress the images using Sharp.
  3. Re-upload the compressed image to S3 bucket A. Note: This step may trigger a recursive call, necessitating the implementation of logic to prevent recursion.

Challenges Faced:

One significant challenge encountered was the need for recursive calls within the same bucket. When a user uploads an image to S3, triggering Lambda to process and store the compressed image back into the same bucket can lead to infinite recursion. To address this, I implemented a tagging mechanism to skip compressed processing. However, this approach resulted in suboptimal function call costs and performance.

Optimization Strategies Implemented:

To mitigate the challenges and enhance performance, I made the following optimizations:

  1. Adjusted socket settings and timeout configurations, setting keepAlive to false to resolve certain issues:
const agentOptions = {
    keepAlive: false,
    maxSockets: 1000, // default 50
};
const httpAgent = new http.Agent(agentOptions);
const httpsAgent = new https.Agent(agentOptions);
const config = {
    region,
    credentials: {
        accessKeyId,
        secretAccessKey,
    },
    forcePathStyle: true,
    requestHandler: new NodeHttpHandler({
        httpAgent: httpAgent,
        httpsAgent: httpsAgent,
    }),
    connectionTimeout: 1000,
    requestTimeout: 5000, // default 0
};
  1. Ensured that the stream is consumed:
    
    const response = await client.send(getObjectcommand);
    const imgData = await response.Body.transformToByteArray(); // consumes the stream
3. Properly destroyed the client when the operation is completed:

```javascript
await client.send(PutCommand);
client.destroy();

By implementing these optimizations, I successfully resolved the recursion issue and improved the overall function duration and performance. Future considerations will include separating the triggering and compression processes after bucket separation.

image
randomhash commented 7 months ago

The problem is still there but in a different shape, right now we receive a bunch of the

Socket timed out without establishing a connection within 1000 ms

The problem is that retry does not really do anything, and just fails the actual request. Does anyone have any ideas for workaround?

cduyzh commented 7 months ago

We are theorizing here without more specific reproduction examples, but one thing to keep in mind is that in the v2 SDK, the S3 objects are buffered by default when you request them (reading the stream).

In v3, the S3::getObject request only opens a stream. You must consume the stream or garbage collect the client or its request handler to keep the connections open to new traffic. One example, reading the stream into a string:

// v2
const get = await s3.getObject({ ... }).promise(); // this buffers (consumes) the stream already.
// v3
const get = await s3.getObject({ ... }); // object .Body has unconsumed stream.
const str = await get.Body.transformToString(); // consumes the stream.

I use "transformToByteArray" , is the same with "transformToString"? const str = await get.Body.transformToByteArray(); // consumes the stream.

RanVaknin commented 3 months ago

@cduyzh , It is the same in the sense that both transformToString and transformToByteArray consumes the stream.


For reference to others that might be running into this issue:

There are multiple workarounds and suggestions on the thread and @kuhe has implemented a warning informing users of socket usage.

Multiple people have commented about the suggestions mentioned on this thread being helpful in mitigating this issue.

If you are experiencing this same problem please review the suggestions on this thread, specifically these:

  1. Consuming the stream by calling transformToString() (now documented here)
  2. Overriding the network request handler on the client to optimize connection management

Thanks, Ran~

10bo commented 3 months ago

We were receiving an exit with code 0 (related: https://github.com/aws/aws-sdk-js-v3/issues/4332, https://github.com/aws/aws-sdk-js-v3/issues/4029 ?) after about 50 requests. Thought it might be useful to share my experience below:

Scripts exiting mid-execution with no error thrown seems like a critical issue. It was incredibly time consuming to debug.

Jarred-Sumner commented 3 months ago

For what it's worth, in Bun v1.1.25 this bug doesn't occur and that's part of what makes @aws-sdk/client-s3 faster in Bun (compared to Node)

❯ bun run.mjs 
cpu: 13th Gen Intel(R) Core(TM) i9-13900
runtime: bun 1.1.25 (x64-linux)

benchmark                 time (avg)             (min … max)       p75       p99      p999
------------------------------------------------------------ -----------------------------
1 KB x 3 s3 upload       203 ms/iter       (195 ms … 213 ms)    211 ms    213 ms    213 ms
1 KB x 3 s3 download     182 ms/iter       (181 ms … 185 ms)    183 ms    185 ms    185 ms

❯ node run.mjs
cpu: 13th Gen Intel(R) Core(TM) i9-13900
runtime: node v22.5.1 (x64-linux)

benchmark                 time (avg)             (min … max)       p75       p99      p999
------------------------------------------------------------ -----------------------------
1 KB x 3 s3 upload       361 ms/iter       (358 ms … 365 ms)    365 ms    365 ms    365 ms
1 KB x 3 s3 download     525 ms/iter       (518 ms … 537 ms)    534 ms    537 ms    537 ms
run.mjs ```js import { S3Client, PutObjectCommand, GetObjectCommand, } from "@aws-sdk/client-s3"; import fs from "node:fs"; import { bench, run } from "mitata"; const bytes = fs.readFileSync(process.argv.at(-1)); const BUCKETS = [""]; const CONCURRENCY = 3; const s3 = new S3Client({ region: "us-west-1", timeout: 10000, credentials: { secretAccessKey: "", accessKeyId: "", }, }); async function testBucket(Bucket) { bench( `${(bytes.byteLength / 1024) | 0} KB x ${CONCURRENCY} s3 upload`, async () => { const promises = new Array(CONCURRENCY); for (let i = 0; i < CONCURRENCY; i++) { promises[i] = s3.send( new PutObjectCommand({ Bucket, Key: `rand/test-${i}.bin`, Body: bytes, }) ); } await Promise.all(promises); } ); bench( `${(bytes.byteLength / 1024) | 0} KB x ${CONCURRENCY} s3 download`, async () => { const promises = new Array(CONCURRENCY); for (let i = 0; i < CONCURRENCY; i++) { promises[i] = s3.send( new GetObjectCommand({ Bucket, Key: `rand/test-${i}.bin`, }) ); } await Promise.all(promises); } ); } for (const Bucket of BUCKETS) { await testBucket(Bucket); } await run({}); ```
QAnders commented 1 week ago

We are running a Lambda with node18 and have recently run into this issue as soon as we hit more than three or four concurrent Lambdas. Then all of a sudden one of the Lambda instances just starting to just silently stop as soon as we try to use GetObjectCommand. As we had declared the S3 client in global scope and the Lambda was "hot" we tried with the work-around to set timeout and tune connection but we just now still got the same issue when we have a heavy load reading from S3 so it seems the connection tuning also hits the ceiling at a point and then we have the same behavior of a silent death...

Anyone that can tell me how to get some kind of logging event or better yet get the Lambda to throw when this happens?

We invoke the Lambda through SQS and use dead-letter queues but as the S3 SDK just happily commits suicide on the Lambda there's no backout to DLQ either and the SQS message is consumed so we are completely in the dark as when this happens!

I've opened two separate support tickets with AWS were they closed the first one blaming our code but the second is still open so happy I found this issue which confirms this is an issue with the SDK and not with our code...

I've now updated our code to re-instantiate the client in every function and "destroy" it once we are done but that gives it a performance hit which is substantial it seems, but is the only reliable work-around it seems...