Understanding usage of the JSII_RUNTIME_PACKAGE_CACHE setting #3895

mcouthon · 2023-01-03T14:10:26Z

mcouthon
Jan 3, 2023

Hello,
I saw that this feature was merged a while back, that is supposed (if I understand it correctly) to allow extracting the JSII tgz archives once, and then reuse them on subsequent calls to JSII.

We're using cdktf with Python, and our main issue is the very long import times for all of the various components. Just the import time on a single module takes 6-15 seconds, and from some profiling I did it looks like the vast majority of this import time is occupied by the JSII kernel.

For a script that only has this line:

from tf_imports import kafka

the majority of the time is spent in jsii/_kernel/providers/process/ProcessProvider.load()

Now, my assumption was that setting the JSII_RUNTIME_PACKAGE_CACHE setting would make the second run much faster, since it wouldn't require the unpacking of the archive again. But it doesn't seem to do anything (or, rather, it isn't working as I expected it to work).

In summary, my two questions are:

When would using the JSII_RUNTIME_PACKAGE_CACHE env var be beneficial?
If I wanted to shorten the import time of python based CDK packages, is there anything on the JSII end that I could do?

Thank you!

(I'll be glad to provide any additional info)

Answered by JJSphar

Feb 27, 2023

It looks like the package cache originally couldn't be enabled due to a string comparison issue with the "enabled" flag. This was fixed in #3912, and released in JSII 1.76.0

Once I upgraded the JSII version in my project, running the JSII_DEBUG=1 JSII_DEBUG_TIMING=1 python -c "from aws_cdk import App" command started to show cache-related output on the first run:
[@jsii/kernel] Package cache enabled, extraction resulted in a cache miss for a total runtime of 70 seconds

A subsequent run produced:
[@jsii/kernel] Package cache enabled, extraction resulted in a cache hit for a total runtime of just 38 seconds.

If you've been having trouble with this feature, try upgrading JSII to >=1.76 and s…

View full answer

JJSphar · 2023-01-04T15:22:48Z

JJSphar
Jan 4, 2023

Thank you for writing this up - I've also tried enabling the JSII_RUNTIME_PACKAGE_CACHE to cut down on Python import times. Running with either the default _CACHE_ROOT location or setting it manually does not appear to store any files in that location, or change the behavior of JSII.

Specifically, I was expecting to see cached files in %LOCALAPPDATA%\AWS\jsii\package-cache on my Windows machine.

0 replies

mcouthon · 2023-01-12T12:58:21Z

mcouthon
Jan 12, 2023
Author

@RomainMuller , sorry to bother you, but perhaps as the creator of the feature you might be able to let us know what are we doing wrong? 🙏

0 replies

RomainMuller · 2023-01-24T10:50:59Z

RomainMuller
Jan 24, 2023

Hey!

The feature is "experimental" at this point, and has had limited testing so far.
You'd expect to see grains from it if you run apps with the same dependencies (same package + version) multiple times, and those are rather large (unpacking is slow / a significant contributor to startup time).

As the documentation on the PR says, you'd enable it via:

Setting JSII_RUNTIME_PACKAGE_CACHE=enabled in your environment
Possibly updating JSII_RUNTIME_PACKAGE_CACHE_ROOT if you don't like the default

The feature is largely developed to "fail safe", so if something goes wrong, it'll fall back to not using the cache silently, so as to avoid crashing if the feature is enabled. This might be what is happening to you there.

You will get additional logging, including about the package cache (when enabled) by running your app with JSII_DEBUG=1, or possibly with JSII_DEBUG_TIMING=1 (will produce much less verbose output, but could be better for getting an initial understanding of what is going on).

On Python specifically, I've had trouble nailing down some slowness in the past (in the Python side of things)... specifically there seems to be a lot of unexplained waiting when reading on the IPC pipe, but I also couldn't reliably reproduce it to try and diagnose it further.

0 replies

mcouthon · 2023-01-25T13:46:45Z

mcouthon
Jan 25, 2023
Author

Thanks for the reply @RomainMuller!

I appreciate that the feature is experimental, so if you tell me that it's not supposed to work yet, that's fine.

FWIW, here's an output of two consecutive runs of the same simple import:

>>> JSII_DEBUG=1 JSII_DEBUG_TIMING=1 JSII_RUNTIME_PACKAGE_CACHE=enabled python -c "from tf_imports import kafka"

> {"name":"constructs","version":"10.1.189","tarball":"/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'constructs',
  version: '10.1.189',
  tarball: '/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]',
  api: 'load'
}
[@jsii/kernel] creating jsii-kernel modules workdir: /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW
< {"ok":{"assembly":"constructs","types":10}}
> {"name":"cdktf","version":"0.14.1","tarball":"/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'cdktf',
  version: '0.14.1',
  tarball: '/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]',
  api: 'load'
}
< {"ok":{"assembly":"cdktf","types":170}}
> {"name":"kafka","version":"0.0.0","tarball":"/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'kafka',
  version: '0.0.0',
  tarball: '/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]',
  api: 'load'
}
< {"ok":{"assembly":"kafka","types":6}}
> {"exit":0}
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/constructs: 15.145ms
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/constructs): 110.145ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/constructs): 4.312ms
[@jsii/kernel:timing] registerAssembly({ name: constructs, types: 10 }): 0.184ms
[@jsii/kernel:timing] load({
  "name": "constructs",
  "version": "10.1.189",
  "tarball": "/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]",
  "api": "load"
}): 133.115ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/cdktf: 201.476ms
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/cdktf): 104.028ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/cdktf): 38.749ms
[@jsii/kernel:timing] registerAssembly({ name: cdktf, types: 170 }): 0.287ms
[@jsii/kernel:timing] load({
  "name": "cdktf",
  "version": "0.14.1",
  "tarball": "/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]",
  "api": "load"
}): 345.674ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/kafka: 4.992s
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/kafka): 70.08ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-XJ6JsW/node_modules/kafka): 4.137ms
[@jsii/kernel:timing] registerAssembly({ name: kafka, types: 6 }): 0.145ms
[@jsii/kernel:timing] load({
  "name": "kafka",
  "version": "0.0.0",
  "tarball": "/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]",
  "api": "load"
}): 5.067s

>>> JSII_DEBUG=1 JSII_DEBUG_TIMING=1 JSII_RUNTIME_PACKAGE_CACHE=enabled python -c "from tf_imports import kafka"

> {"name":"constructs","version":"10.1.189","tarball":"/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'constructs',
  version: '10.1.189',
  tarball: '/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]',
  api: 'load'
}
[@jsii/kernel] creating jsii-kernel modules workdir: /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA
< {"ok":{"assembly":"constructs","types":10}}
> {"name":"cdktf","version":"0.14.1","tarball":"/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'cdktf',
  version: '0.14.1',
  tarball: '/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]',
  api: 'load'
}
< {"ok":{"assembly":"cdktf","types":170}}
> {"name":"kafka","version":"0.0.0","tarball":"/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]","api":"load"}
[@jsii/kernel] load {
  name: 'kafka',
  version: '0.0.0',
  tarball: '/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]',
  api: 'load'
}
< {"ok":{"assembly":"kafka","types":6}}
> {"exit":0}
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/constructs: 14.722ms
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/constructs): 110.579ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/constructs): 3.87ms
[@jsii/kernel:timing] registerAssembly({ name: constructs, types: 10 }): 0.171ms
[@jsii/kernel:timing] load({
  "name": "constructs",
  "version": "10.1.189",
  "tarball": "/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/constructs/_jsii/[email protected]",
  "api": "load"
}): 132.158ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/cdktf: 198.406ms
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/cdktf): 103.265ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/cdktf): 39.563ms
[@jsii/kernel:timing] registerAssembly({ name: cdktf, types: 170 }): 0.29ms
[@jsii/kernel:timing] load({
  "name": "cdktf",
  "version": "0.14.1",
  "tarball": "/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/[email protected]",
  "api": "load"
}): 342.563ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]) => /var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/kafka: 5.203s
[@jsii/kernel:timing] loadAssemblyFromPath(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/kafka): 68.643ms
[@jsii/kernel:timing] require(/var/folders/cy/61tf7f5s1_b9139k56p43yf80000gn/T/jsii-kernel-ImZloA/node_modules/kafka): 4.513ms
[@jsii/kernel:timing] registerAssembly({ name: kafka, types: 6 }): 0.15ms
[@jsii/kernel:timing] load({
  "name": "kafka",
  "version": "0.0.0",
  "tarball": "/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/[email protected]",
  "api": "load"
}): 5.278s

As you can see, both runs are ~5 seconds, with the vast majority of this time being spent on extracting the tar. My assumption would've been that with the setting set, JSII would know to reuse the same extracted folder.

Anything I could be doing differently?

0 replies

JJSphar · 2023-02-27T19:47:32Z

JJSphar
Feb 27, 2023

It looks like the package cache originally couldn't be enabled due to a string comparison issue with the "enabled" flag. This was fixed in #3912, and released in JSII 1.76.0

Once I upgraded the JSII version in my project, running the JSII_DEBUG=1 JSII_DEBUG_TIMING=1 python -c "from aws_cdk import App" command started to show cache-related output on the first run:
[@jsii/kernel] Package cache enabled, extraction resulted in a cache miss for a total runtime of 70 seconds

A subsequent run produced:
[@jsii/kernel] Package cache enabled, extraction resulted in a cache hit for a total runtime of just 38 seconds.

If you've been having trouble with this feature, try upgrading JSII to >=1.76 and see if that helps.

1 reply

mcouthon Apr 23, 2023
Author

Thank you. Upgrading to 1.76.0 did indeed solve my problems, and subsequent imports are now quite a bit faster!

2023-12-01T20:07:34Z

github-actions[bot]
bot Dec 1, 2023

Hello! Reopening this discussion to make it searchable.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Understanding usage of the JSII_RUNTIME_PACKAGE_CACHE setting #3895

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 6 comments 1 reply

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Understanding usage of the JSII_RUNTIME_PACKAGE_CACHE setting #3895

mcouthon Jan 3, 2023

Replies: 6 comments · 1 reply

JJSphar Jan 4, 2023

mcouthon Jan 12, 2023 Author

RomainMuller Jan 24, 2023

mcouthon Jan 25, 2023 Author

JJSphar Feb 27, 2023

mcouthon Apr 23, 2023 Author

github-actions[bot] bot Dec 1, 2023

mcouthon
Jan 3, 2023

Replies: 6 comments 1 reply

JJSphar
Jan 4, 2023

mcouthon
Jan 12, 2023
Author

RomainMuller
Jan 24, 2023

mcouthon
Jan 25, 2023
Author

JJSphar
Feb 27, 2023

mcouthon Apr 23, 2023
Author

github-actions[bot]
bot Dec 1, 2023