awscli takes very long to start

[MartinLoeper]

I just installed the awscli using this layer's recipe and noticed that it performs very badly on the vexpress-qemu machine (1 cpu core) and the orange-pi-zero (quad-core Cortex-A7):

root@vexpress-qemu:~# time aws
Note: AWS CLI version 2, the latest major version of the AWS CLI, is now stable and recommended for general use. For more information, see the AWS CLI version 2 installation instructions at: https://docs.aws.amazon.com/cli/latest/userguide/install-cliv2.html

usage: aws [options] <command> <subcommand> [<subcommand> ...] [parameters]
To see help text, you can run:

  aws help
  aws <command> help
  aws <command> <subcommand> help
aws: error: the following arguments are required: command

real    0m53.152s
user    0m7.821s
sys     0m5.827s

Subsequent executions are a bit faster but still perform consistently bad:

root@vexpress-qemu:~# time aws
[...]
real    0m6.911s
user    0m6.426s
sys     0m0.396s

I figured out that most of the time is spent during importlib._bootstrap - particularly importing stuff like urllib3. This is also confirmed by observing time python3 -c "import urllib3" which yields:

real    0m1.491s
user    0m1.372s
sys     0m0.079s

I noticed people also talking about python import resolution speed e.g. here. However, I am no python expert. Can someone tell me why awscli takes so long to start / initialize on my iot devices and only a fraction of the time when run on a single cpu core of my laptop?

[rpcme]

Hello @MartinLoeper sorry for not responding earlier.

The first run duration could be building pyc files. I am only guessing since I am not one of the AWS CLI developers.

Will try to get someone who can explain more deeply.

[MartinLoeper]

Hi @rpcme,

Thanks for offering help!
I can also share some yocto configuration files in kas format if you want to reproduce the behaviour for a qemuarm machine.

[rpcme]

@MartinLoeper Can we please ask more information - what are the timings for first run and second run by using --debug flag, developers say this will give more clues.

We will then analyze and see what the next step should be such as reproducing.

[MartinLoeper]

root@orange-pi-zero:~# time aws --debug
Note: AWS CLI version 2, the latest major version of the AWS CLI, is now stable and recommended for general use. For more information, see the AWS CLI version 2 installation instructions at: https://docs.aws.amazon.com/cli/latest/userguide/install-cliv2.html

usage: aws [options] <command> <subcommand> [<subcommand> ...] [parameters]
To see help text, you can run:

  aws help
  aws <command> help
  aws <command> <subcommand> help
aws: error: the following arguments are required: command

real    0m10.325s
user    0m6.119s
sys     0m0.717s

Subsequent runs yield:

time aws --debug
Note: AWS CLI version 2, the latest major version of the AWS CLI, is now stable and recommended for general use. For more information, see the AWS CLI version 2 installation instructions at: https://docs.aws.amazon.com/cli/latest/userguide/install-cliv2.html

usage: aws [options] <command> <subcommand> [<subcommand> ...] [parameters]
To see help text, you can run:

  aws help
  aws <command> help
  aws <command> <subcommand> help
aws: error: the following arguments are required: command

real    0m5.397s
user    0m5.188s
sys     0m0.207s

Version:

root@orange-pi-zero:~# aws --version
aws-cli/1.19.36 Python/3.8.10 Linux/5.4.111 botocore/1.20.36

[rpcme]

Well that doesn't look like anything :(

[gshondal]

Hey @MartinLoeper,

The user+sys is what you're going to want to look at for the time the aws cli took to run. The real time is the full time including any time the cpu spent on other processes (think context-switching). If this is a single core and the real time is much higher, this means there are other processes that are using the processor when the aws cli was executed.

Decreasing the overall cpu usage will decrease the difference between the real time and the user+sys time of the command.

[rpcme]

Hello @MartinLoeper can you let me know your config. I'll try to find time to run it through strace to see if we're getting slowdown anywhere that way.

You might try the same if convenient to locate any bad smells.

Also can you let me know if the orange pi zero is the same spec as raspberry pi zero. I don't have the former but I do have the latter.

[MartinLoeper]

Hi @rpcme, strace is a good idea. However, I already tried it and could not find anything wrong.

I just noticed that many many files are opened due to python imports and boto3 loaders - particularly service model loaders.

You further reminded me of our company also possessing a bunch of Raspberry Pis...
I will check the timings for the rpi 4b once I am back from vacation.
Thanks for your patience and your willingness to help!

[rpcme]

Hi @MartinLoeper I'll just check back weekly to see when you're back from vacation. I'm looking forward to seeing progress.

[rpcme]

Hi @MartinLoeper just checking in to see if you have had a chance to repro? Would love to get this ticket closed :)

[MartinLoeper]

Hi @rpcme, I'm back! Thanks for the mention.

I ran the aws-cli on our raspberrypi 4b and got the following result:

root@raspberrypi4:~# time aws --debug
Note: AWS CLI version 2, the latest major version of the AWS CLI, is now stable and recommended for general use. For more information, see the AWS CLI version 2 installation instructions at: https://docs.aws.amazon.com/cli/latest/userguide/install-cliv2.html

usage: aws [options] <command> <subcommand> [<subcommand> ...] [parameters]
To see help text, you can run:

  aws help
  aws <command> help
  aws <command> <subcommand> help
aws: error: the following arguments are required: command

real    0m5.648s
user    0m3.422s
sys     0m0.833s

Second run:

root@raspberrypi4:~# time aws --debug
Note: AWS CLI version 2, the latest major version of the AWS CLI, is now stable and recommended for general use. For more information, see the AWS CLI version 2 installation instructions at: https://docs.aws.amazon.com/cli/latest/userguide/install-cliv2.html

usage: aws [options] <command> <subcommand> [<subcommand> ...] [parameters]
To see help text, you can run:

  aws help
  aws <command> help
  aws <command> <subcommand> help
aws: error: the following arguments are required: command

real    0m3.857s
user    0m3.268s
sys     0m0.591s

You can reproduce the yocto image with the kas manifest in the following repo: https://github.com/MartinLoeper/meta-aws-issue-159/

I enabled the serial port via UART to connect to the device.

[MartinLoeper]

I can also share the fully built sdimg file with you if you want to.

[rpcme]

Martin, I am experiencing the same issue on a RISC-V board. I am not exactly sure what it is but I really don't know if it's a meta-aws problem. But it's definitely a problem. Really, it is horrible invoking the aws cli and waiting for seconds for it to even start.

I did start invoking the API calls individually and it isn't the python interpreter that takes time, it is the CLI initializer code. I really don't know anything about python profiling so a bit at a loss.

[rpcme]

@MartinLoeper I am asking for help from experts maintaining meta-python. While I can't promise a fast solution, I just wanted to let you know I am looking for more avenues to help.

[MartinLoeper]

Thanks @rpcme! This issue is currently not as urgent because I could try a workaround using SDKs I guess. Nonetheless, great you are so supportive! Really appreciating it!

[rpcme]

This is really great news @MartinLoeper. I will keep it open until resolved because ... well ... I want to use it on workstation class distribution on RISC-V - but can't exactly do that if it takes 4-8 seconds to invoke every command :D

[MartinLoeper]

Understandable! Hope someone has a clue what is going wrong there.

[rpcme]

@MartinLoeper

I have not forgotten this issue. The next step will be to file a YP bugzilla bug after narrowing the slow module load problem. After running cProfile I noted that module load times are excessive. When invoking python3 -X dev /usr/bin/aws and see the following output but I can't find any information related to _SixMetaPathImporter.

root@qemux86-64:~# python3 -X dev /usr/bin/aws
<frozen importlib._bootstrap>:914: ImportWarning: _SixMetaPathImporter.find_spec() not found; falling back to find_module()
<frozen importlib._bootstrap>:914: ImportWarning: _SixMetaPathImporter.find_spec() not found; falling back to find_module()
<frozen importlib._bootstrap>:671: ImportWarning: _SixMetaPathImporter.exec_module() not found; falling back to load_module()
<frozen importlib._bootstrap>:914: ImportWarning: _SixMetaPathImporter.find_spec() not found; falling back to find_module()
<frozen importlib._bootstrap>:671: ImportWarning: _SixMetaPathImporter.exec_module() not found; falling back to load_module()

[thomas-roos]

I think it's a botocore problem, as mentioned here: boto/botocore#2553

[rpcme]

I think that we can resolve this issue as wont-fix from a meta-aws perspective.