Understanding usage of the JSII_RUNTIME_PACKAGE_CACHE setting

[mcouthon]

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:

1. When would using the JSII_RUNTIME_PACKAGE_CACHE env var be beneficial?
2. 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)

[JJSphar]

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.

[mcouthon]

@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? 🙏

[RomainMuller]

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.

[mcouthon]

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/constructs@10.1.189.jsii.tgz","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/constructs@10.1.189.jsii.tgz',
  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/cdktf@0.14.1.jsii.tgz","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/cdktf@0.14.1.jsii.tgz',
  api: 'load'
}
< {"ok":{"assembly":"cdktf","types":170}}
> {"name":"kafka","version":"0.0.0","tarball":"/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz","api":"load"}
[@jsii/kernel] load {
  name: 'kafka',
  version: '0.0.0',
  tarball: '/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz',
  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/constructs@10.1.189.jsii.tgz) => /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/constructs@10.1.189.jsii.tgz",
  "api": "load"
}): 133.115ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/cdktf@0.14.1.jsii.tgz) => /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/cdktf@0.14.1.jsii.tgz",
  "api": "load"
}): 345.674ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz) => /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/kafka@0.0.0.jsii.tgz",
  "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/constructs@10.1.189.jsii.tgz","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/constructs@10.1.189.jsii.tgz',
  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/cdktf@0.14.1.jsii.tgz","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/cdktf@0.14.1.jsii.tgz',
  api: 'load'
}
< {"ok":{"assembly":"cdktf","types":170}}
> {"name":"kafka","version":"0.0.0","tarball":"/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz","api":"load"}
[@jsii/kernel] load {
  name: 'kafka',
  version: '0.0.0',
  tarball: '/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz',
  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/constructs@10.1.189.jsii.tgz) => /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/constructs@10.1.189.jsii.tgz",
  "api": "load"
}): 132.158ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/.pyenv/versions/rugatka/lib/python3.8/site-packages/cdktf/_jsii/cdktf@0.14.1.jsii.tgz) => /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/cdktf@0.14.1.jsii.tgz",
  "api": "load"
}): 342.563ms
[@jsii/kernel:timing] tar.extract(/Users/pavel_brodsky/dev/rugatka/tf_imports/kafka/_jsii/kafka@0.0.0.jsii.tgz) => /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/kafka@0.0.0.jsii.tgz",
  "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?

[JJSphar]

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.

[mcouthon]

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

[github-actions[bot]]

Hello! Reopening this discussion to make it searchable.