SAM: slow build time when building multiple functions

[risingdivik]

Describe the bug

I am trying to Debug using vs code and AWS toolkit .. when I click on debug it builds it successfully but when it calls sam invoke it tries to search it the built folder but is not able to find it there.

To Reproduce
Build the project, add the configuration in launch.json
and click on the debug

Expected behavior

I am not able to debug and it is taking 40 min in order to get to the error.

Screenshots

Desktop (please complete the following information):

OS: Windows

VS Code About
Version: 1.60.0 (system setup)
Commit: e7d7e9a9348e6a8cc8c03f877d39cb72e5dfb1ff
Date: 2021-09-01T10:41:52.311Z
Electron: 13.1.8
Chrome: 91.0.4472.164
Node.js: 14.16.0
V8: 9.1.269.39-electron.0
OS: Windows_NT x64 10.0.18363

Toolktit Version: AWS Toolkit v1.29.0
Docer Version : v1.16.1

Additional context

[risingdivik]

SAM CLI, version 1.31.0
OS:Windows
AWS region: eu-central-1

[risingdivik]

I am getting this in info...
Built Template : ....\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkINCgrY\output\template.yaml

But no template is getting generated at this path..

This is the verbose info
SAM: command exited (code: null): PID 18212: [C:\Program Files\Amazon\AWSSAMCLI\bin\sam.cmd local invoke --debug abcFunction --template C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkINCgrY\output\template.yaml --event C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkINCgrY\event.json --env-vars C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkINCgrY\env-vars.json -d 5858 --skip-pull-image]

[JadenSimon]

40 min in order to get to the error.

It's taking 40 minutes to build? Also, what runtime is this? Currently, the build part of the process does not refresh the timeout timer, so it ends up timing out after the build unfortunately. Some additional logging output from the build step could be useful.

In the meantime, you can bump the timeout time by looking for the setting aws.samcli.lambda.timeout in VS Code. This is in milliseconds so you'll need quite a large number, maybe ~3000000. I'd also change the aws.logLevel setting to 'debug' to output more information. Then we can look into why the build is taking so long.

[risingdivik]

I have already increased the timeout to 5 mins
Its a node.js project.

[JadenSimon]

The timeout includes the build step as well. What exactly is taking so long with the build step? Log output during the build step would be helpful if it doesn't contain any sensitive info.

[risingdivik]

Actually, if I try to run this command sam invoke manually through the AWS sam CLI, it works if I change the template path to project directory not build folder in temp.
So I feel there is not an issue with the timeout but it is with the Built Template path.
Let me try extracting the more build info

[risingdivik]

@JadenSimon

2021-09-13 11:53:07 [INFO]:
Build Succeeded

2021-09-13 11:53:07 [INFO]:
Built Artifacts : ....\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkoix4CJ\output
Built Template : ....\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkoix4CJ\output\template.yaml

Commands you can use next

[] Invoke Function: sam local invoke -t ....\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkoix4CJ\output\template.yaml
[] Deploy: sam deploy --guided --template-file ....\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctkoix4CJ\output\template.yaml

2021-09-13 11:53:08 [INFO]: 2021-09-13 11:53:08,006 | Sending Telemetry: {'metrics': [{'commandRun': {'requestId': 'c9c25f8a-53db-4fd3-9f6eaasdddf', 'installationId': '1a826a9e-a1b6-4433-a466-516974faa653', 'sessionId': '0099eec7-c7c4-4d57-be4d-eacfda4e810e', 'executionEnvironment': 'CLI', 'ci': False, 'pyversion': '3.8.8', 'samcliVersion': '1.31.0', 'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam build', 'duration': 2646025, 'exitReason': 'success', 'exitCode': 0}}]}

2021-09-13 11:53:10 [INFO]: 2021-09-13 11:53:10,431 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=2)

2021-09-13 11:53:10 [INFO]: Build complete.
2021-09-13 11:53:10 [INFO]: Starting SAM application locally
2021-09-13 11:53:10 [INFO]: AWS.running.command
2021-09-13 11:53:11 [ERROR]: Timeout while waiting for command: "sam local invoke"
2021-09-13 11:53:11 [ERROR]: Failed to run SAM application locally: Timeout while waiting for command: "sam local invoke"

Command stopped: "sam local invoke"

[risingdivik]

I will not able to share many logs...Can it be an issue related to Telemetry?

[risingdivik]

@JadenSimon
Other things might be useful to you
2021-09-14 23:51:16 [INFO]: 2021-09-14 23:51:16,534 | Using config file: samconfig.toml, config environment: default
Do i need to make any changes in this file?

2021-09-14 23:51:20 [INFO]: 2021-09-14 23:51:20,866 | --base-dir is not presented, adjusting uri . relative to
C:\project\artifacts\app\my-app\app___vsctk___template.yaml

2021-09-14 23:51:21 [INFO]: 2021-09-14 23:51:21,377 | Unique function build definition found, adding as new (

After this step its taking lot of time
2021-09-14 23:52:55,056 | NodejsNpmBuilder:CleanUpNpmrc succeeded

Every time i start debug,
it created a new folder of size 1.30 GB approx at C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode

SAM: command exited (code: null): PID 2064:

[JadenSimon]

Can it be an issue related to Telemetry?

Unlikely, though we ought to be cleaning up errors rather than logging them like that.

it created a new folder of size 1.30 GB approx at C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode

Are they not being deleted? This is separate (but important) bug.

Using config file: samconfig.toml,

Ah this could be it. The 'Timeout while waiting for command' was throwing me off, making me think the timing was the issue. Just to be sure, the time between the start of the build and the start of local invoke is less than the timeout time you set correct?

Our support for samconfig.toml is lacking at the moment; we don't parse it at all. There could be things within that config file that causes an incompatibility with the debugging workflow. For example, setting your own base/build directories in the config file could cause a conflict.

[risingdivik]

More Info
Initially, I was getting errors with python's latest version, So I installed Python 3.8.10 specifically.

Also, I have one more system(not having access currently) on which I set it up 1 month ago, it's working perfectly fine on it....However, taking 40 mins on it...but at least I was able to debug it... Even the timeout was also not manipulated on that

Something i found in template.yml
Function:
Runtime: nodejs14.x
MemorySize: 128
Timeout: 100
Is this timeout and memory also linked?

[JadenSimon]

Timeout: 100

This timeout is separate from the debugging timeout, so it wouldn't have an impact. Are you able to debug a basic SAM application? You can create one using the Create Lambda SAM Application command from the command palette.

[risingdivik]

I think I made that silly mistake. You were right, I increased it from 5 minutes to 1 hour (3,600,000) and it worked...
Now the main issue is related to time

One last question
As template.yml contains various Type: AWS::Serverless::Function. So its taking time in copying the artifacts

2021-09-15 00:37:07 [INFO]: 2021-09-15 00:37:07,130 | Copying artifacts from C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctk4l5CEL\output\aFunction to C:\Users\divi\AppData\Local\Temp\aws-toolkit-vscode\vsctk4l5CEL\output\bFunction

So in order to copy every function, it takes around 1.5 min and I have 15 such function.
So anything can be done to make it faster.

[JadenSimon]

Does it still take around ~40 min to build with just SAM CLI alone?
I'm sure there's ways we can optimize the build process, especially if it's something the Toolkit is doing that's causing SAM CLI to do more work than it needs to. Copying ~1.3 GB to a new directory every build is definitely not good.

This blog post has some parameters you can try. You can add them to the build command by adding buildArguments to your launch.json configuration:

"sam": {
        "buildArguments": ["arg1", "arg2", "arg3"]
}

If none of that works, it's possible that SAM CLI is unable to do any caching since we are creating temporary directories for each run/debug loop. So the toolkit might need to figure out a way to preserve build artifacts per user-workspace, or at least have this be configurable.

[justinmk3]

Currently, the build part of the process does not refresh the timeout timer, so it ends up timing out after the build unfortunately.

Related: 5e522a7

it's possible that SAM CLI is unable to do any caching since we are creating temporary directories for each run/debug loop. So the toolkit might need to figure out a way to preserve build artifacts per user-workspace, or at least have this be configurable.

We have plans to remove/avoid the need for the temporary directory. Related: #1988

[risingdivik]

As of now, I tried to keep only one function in template.yml, which I want to debug and now the performance is good.

But facing another issue related to AWS X-RAY
Missing AWS Lambda trace data for X-Ray. Ensure Active Tracing is enabled and no subsegments are created outside the function handler

[JadenSimon]

Could this issue be relevant? aws/aws-sam-cli#217
Looks like SAM CLI doesn't plan on supporting X-Ray locally.

[risingdivik]

not relevant to this and I will try adding build arguments tomorrow.

[risingdivik]

@JadenSimon @justinmk3
I tried adding build arguments in the launch.json
"sam":{
"buildArguments": ["--cached","--parallel"]
}

Stack Trace

021-09-18 04:03:25 [INFO]: Traceback (most recent call last):
File "pathlib.py", line 1287, in mkdir
FileNotFoundError: [WinError 3] The system cannot find the path specified: '.aws-sam\cache'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "runpy.py", line 194, in _run_module_as_main
File "runpy.py", line 87, in run_code
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli_main.py", line 12, in
cli(prog_name="sam")
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 829, in call
return self.main(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 782, in main
rv = self.invoke(ctx)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 1259, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 1066, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 610, in invoke
return callback(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\decorators.py", line 73, in new_func
return ctx.invoke(f, obj, *args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\click\core.py", line 610, in invoke
return callback(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\lib\telemetry\metric.py", line 153, in wrapped
raise exception # pylint: disable=raising-bad-type
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\lib\telemetry\metric.py", line 122, in wrapped
return_value = func(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\lib\utils\version_checker.py", line 42, in wrapped
actual_result = func(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\cli\main.py", line 90, in wrapper
return func(*args, **kwargs)
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\commands\build\command.py", line 210, in cli
do_cli(
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\commands\build\command.py", line 279, in do_cli
with BuildContext(
File "C:\Program Files\Amazon\AWSSAMCLI\runtime\lib\site-packages\samcli\commands\build\build_context.py", line 111, in enter
cache_path.mkdir(mode=self._BUILD_DIR_PERMISSIONS, parents=True, exist_ok=True)
File "pathlib.py", line 1291, in mkdir
File "pathlib.py", line 1287, in mkdir
PermissionError: [WinError 5] Access is denied: '.aws-sam'

[justinmk3]

FileNotFoundError: [WinError 3] The system cannot find the path specified: '.aws-sam\cache'

Looks related to the Toolkit's use of a temporary build dir #2050

[JadenSimon]

@risingdivik

A potential workaround may be to specify --cache-dir as an absolute path.

[justinmk3]

See this comment for how to use --build-dir in AWS Toolkit 1.30.0.