Fork me on GitHub
#graalvm
<
2021-09-09
>
Chris Lowe08:09:54

Morning all I’ve come across a curious runtime quirk regarding the slow initialisation of the Cognitect AWS API in Lambda. My code uses Holy Lambda and is natively compiled with GraalVM. In summary, I’m sending an SQS message and for a cold start up, the initialisation is very slow - about 2 seconds. However, I have other lambda functions, same util function, that do not exhibit the same slow down: the first SQS call is about 180ms on a cold start. After diving deeper into this, The slowdown seems to be related to memory. Same code, different memory settings:

BEFORE (Mem 192 MB):

REPORT RequestId: ca6134cd-cc0c-5d20-b6dc-6d7f3f9173b4	Duration: 3110.14 ms	Billed Duration: 3348 ms	Memory Size: 192 MB	Max Memory Used: 137 MB	Init Duration: 237.14 ms	


AFTER (Mem 2000 MB):

REPORT RequestId: 760df43d-ded0-5dff-97ae-ad8e1873c3ff Duration: 425.65 ms Billed Duration: 718 ms Memory Size: 2000 MB Max Memory Used: 142 MB Init Duration: 291.85 ms 
I found this to be surprising. For regular Java, I get it - you’d be stressing the different mem generations by splitting up such a small amount of RAM. But GraalVM - I’m not sure if that’s a thing or not Even so, as you can see, the reported memory used is 142 MB in both cases which is well under both memory specifications. Can anyone offer some insight into this? Or advice on how to choose the right amount of memory?

Chris Lowe08:09:37

For reference, SQS util function is this:

(ns sqs-utils
  (:require
    [io.pedestal.log :as log]
    [cognitect.aws.client.api :as aws]
    [ai.scalably.lambda.common.aws-utils :refer [http-client]]))


(def sqs (delay (aws/client {:api         :sqs
                             :http-client @http-client})))

(defn send-sqs-message!
  [{:keys [queue-url, msg] :as request}]
  (log/debug :in 'send-sqs-message! :request request)
  (let [result (time (aws/invoke @sqs {:op      :SendMessage
                                       :request {:QueueUrl    queue-url
                                                 :MessageBody msg}}))
        error-message (or (:cognitect.anomalies/message result) (get-in result [:ErrorResponse :Error :Message]))]
    (if error-message
      (log/error :in 'send-sqs-message! :message "Failed to send SQS message" :error-message error-message :request request :result result)
      (log/info :in 'send-sqs-message! :message "Sent SQS message" :request request :result result))

    (:MessageId result)))

Chris Lowe09:09:37

At the advice of @UJ1339K2B I’ve raised this on the GraalVM Slack channel https://graalvm.slack.com/archives/CN9KSFB40/p1631178165056200 I’ll post back any findings here.

souenzzo12:09:58

it may be related with memory pressure with max at 200, when you reach 100, it is 50% with max at 2000, when you reach 100, it is 5% 50% will trigger GC methods more than 5% Not sure if you can connect something like a visualvm into your app. visualvm will show gc activity

Chris Lowe06:09:37

@U2J4FRT2T thanks for this. I’m operating on this assumption also. Lambdas are ephemeral and locked down, so being able to use visual vm is unlikely. You can get the JVM to log GC activity. Been a while since I’ve pored through such content, but I think that’s my only option.

lread16:09:21

Hey ho! We’ve moved lread/clj-graal-docs to clj-easy/graal-docs This happy new home better reflects that it is a community-built set of docs.

🚀 4
gratitude 2
lread16:09:09

(Thanks to @borkdude and @ericdallo for creating the new clj-easy github org!)

lread16:09:47

Ha! You caught that!

Alex Miller (Clojure team)16:09:09

well, I watched Simple Made Easy like 10 times last week

lread16:09:59

I think @borkdude might have been mirthfully trolling a bit there with the org name. simple_smile

borkdude16:09:15

we chose this name to not become too popular within the community

borkdude16:09:49

so we don't have to deal with lots of PRs, we're also considering JIRA and mailing patches :P

lread16:09:00

snail mail only, of course.

borkdude16:09:19

nice, like chess via snail mail

lread16:09:46

Patches must be handwritten only and… base64 encoded.

😆 4
Joshua Suskalo16:09:03

The base-64 code is read via OCR, and if the final result of the patch is not syntactically-correct Clojure code, the entire suggestion is disregarded out of hand.

😅 4
Ben Sless20:09:09

All that bother for "fixed typo" 😄

Joshua Suskalo16:09:01

After all, if it wasn't worth spending the time to get it right the first time, it wasn't worth it at all.

lread16:09:20

If you don’t hear back from us in 3 years, please assume rejection and consider resubmitting, but please, more carefully.

borkdude16:09:15

Some projects have a thing like that: stalebot

Joshua Suskalo16:09:41

that sounds like something that'd come out of the js ecosystem

borkdude16:09:42

Don't PR us, we'll PR you

😂 6
2
lread16:09:48

Thanks, I haven’t laughed so hard in a GraalVM chat channel in ages.

borkdude16:09:06

The final joke then.

lread16:09:26

My wife just walked in asked me what I was laughing at…

Joshua Suskalo16:09:48

I gotta question if the coffee brown color for java was intentional or a happy coincidence for github's language colors.

Alex Miller (Clojure team)16:09:02

on the upside, this did cause me to register http://knittedcastle.org

😂 6
borkdude16:09:31

if you have a cool logo with a knitted castle, happy to use it for the org!

lread16:09:04

I’ve been know to make a logo or two… but… I just dunno if I can do it…

borkdude17:09:41

For now I quite like the logo that @ericdallo put together

metal 4
borkdude18:09:48

@ericdallo it works: https://github.com/clj-easy/graal-build-time also: I used tools.build and bb tasks together :)

borkdude18:09:22

Still need to insert the logic that collects all the packages but that's the trivial part

ericdallo19:09:28

Oh, that's awesome!

ericdallo19:09:23

really simple indeed, that's good

borkdude19:09:23

I'm now making it work for reals

borkdude19:09:58

ok, it should work now @ericdallo, try bb native-image-test

loading 2
borkdude19:09:31

[native-test:73977]    classlist:   1,082.78 ms,  0.96 GB
[native-test:73977]        (cap):   1,431.59 ms,  0.96 GB
Registering packages for build time initialization: clojure, clj_easy

Asko Nōmm19:09:54

Oooh this is awesome @borkdude!!!!!

ericdallo19:09:12

Yeah, it works @borkdude I can release a local jar and test with clojure-lsp :)

borkdude19:09:05

yeah please test. one thing I have doubts about is whether this Feature class sees the classpath of the app under build or not

👍 2
borkdude20:09:02

@ericdallo Testing locally...

borkdude20:09:09

with babashka

borkdude20:09:48

hmm, I think the lib needs to also require the main class first

borkdude20:09:56

else clojure won't see the relevant namespaces

borkdude20:09:12

or we should find a different way to enumerate those packages

ericdallo20:09:19

hum, good point

borkdude20:09:24

perhaps by looking at __main.class etc

ericdallo20:09:59

it seems harder

borkdude20:09:55

I added an install task

borkdude20:09:58

bb install

👍 2
borkdude20:09:04

ok, it's a little bit harder than this apparently

borkdude20:09:09

but we will get there

🙏 2
ericdallo20:09:59

Should I test with clojure-lsp without this main.class change?

ericdallo20:09:06

or it's for sure it won't work?

borkdude20:09:25

I haven't changed that yet

borkdude20:09:29

but I don't think it works

borkdude20:09:39

because the classpath isn't the classpath of the app

ericdallo20:09:15

oh, getApplicationClassPath() looks promising

borkdude21:09:09

almost there

borkdude21:09:43

Should work now, testing with bb

borkdude21:09:10

Registering packages for build time initialization: clojure, rewrite_clj.interop, rewrite_clj.zip, rewrite_clj.node, rewrite_clj.parser.namespaced_map, rewrite_clj.parser.whitespace, rewrite_clj.parser.token, rewrite_clj.parser.core, rewrite_clj.parser.keyword, rewrite_clj.parser.string, rewrite_clj.zip.subedit, rewrite_clj.zip.move, rewrite_clj.zip.whitespace, rewrite_clj.zip.context, rewrite_clj.zip.findz, rewrite_clj.zip.seqz, rewrite_clj.zip.removez, rewrite_clj.zip.base, rewrite_clj.zip.editz, rewrite_clj.zip.insert, rewrite_clj.zip.walk, rewrite_clj.parser, rewrite_clj.custom_zipper.utils, rewrite_clj.custom_zipper.switchable, rewrite_clj.custom_zipper.core, rewrite_clj.paredit, rewrite_clj.reader, rewrite_clj.node.namespaced_map, rewrite_clj.node.comment, rewrite_clj.node.regex, rewrite_clj.node.fn, rewrite_clj.node.reader_macro, rewrite_clj.node.coercer, rewrite_clj.node.whitespace, rewrite_clj.node.meta, rewrite_clj.node.protocols, rewrite_clj.node.forms, rewrite_clj.node.token, rewrite_clj.node.integer, rewrite_clj.node.seq, rewrite_clj.node.extras, rewrite_clj.node.uneval, rewrite_clj.node.keyword, rewrite_clj.node.stringz, rewrite_clj.node.quote, org.httpkit.sni_client, org.httpkit.server, org.httpkit.client, org.httpkit.encode, cognitect.transit, sci.impl.vars, sci.impl.faster, sci.impl.interop, sci.impl.hierarchies, , sci.impl.for_macro, sci.impl.reify, sci.impl.fns, sci.impl.multimethods, sci.impl.analyzer, sci.impl.unrestrict, sci.impl.load, sci.impl.protocols, sci.impl.types, sci.impl.doseq_macro, sci.impl.records, sci.impl.interpreter, sci.impl.resolve, sci.impl.utils, sci.impl.parser, sci.impl.callstack, sci.impl.macros, sci.impl.opts, sci.impl.proxy, sci.impl.read, sci.impl.evaluator, sci.impl.core_protocols, sci.impl.destructure, sci.impl.namespaces, sci.addons, sci.addons.future, sci.core, sci.lang, io.aviso.ansi, io.aviso.columns, io.aviso.exception, edamame.impl.parser, edamame.impl.read_fn, edamame.impl.syntax_quote, flatland.ordered.common, flatland.ordered.map, flatland.ordered.set, bencode.core, taoensso.timbre, taoensso.encore, taoensso.truss, taoensso.timbre.appenders.core, taoensso.truss.impl, hf.depstar.uberjar, clj_yaml.core, cheshire.core, cheshire.factory, cheshire.generate_seq, cheshire.generate, cheshire.parse, selmer.tags, selmer.filter_parser, selmer.filters, selmer.util, selmer.parser, selmer.template_parser, selmer.validator, hiccup.util, hiccup.compiler, babashka.impl.rewrite_clj, babashka.impl.bencode, babashka.impl.yaml, babashka.impl.csv, babashka.impl.httpkit_client, babashka.impl.tools.cli, babashka.impl.cheshire, babashka.impl.common, babashka.impl.reify, babashka.impl.server, babashka.impl.error_handler, babashka.impl.clojure.zip, babashka.impl.clojure.core.server, babashka.impl.clojure.test.check, , babashka.impl.clojure.java.shell, babashka.impl.clojure.java.browse, babashka.impl.clojure.data, babashka.impl.clojure.core, babashka.impl.clojure.test, babashka.impl.clojure.stacktrace, babashka.impl.clojure.main, babashka.impl.curl, babashka.impl.deps, babashka.impl.match, babashka.impl.socket_repl, babashka.impl.httpkit_server, babashka.impl.protocols, babashka.impl.hiccup, babashka.impl.data, babashka.impl.classes, babashka.impl.xml, babashka.impl.features, babashka.impl.datafy, babashka.impl.logging, babashka.impl.pprint, babashka.impl.print_deps, babashka.impl.tasks, babashka.impl.proxy, babashka.impl.test, babashka.impl.repl, babashka.impl.process, babashka.impl.sigint_handler, babashka.impl.transit, babashka.impl.async, babashka.impl.pipe_signal_handler, babashka.impl.selmer, babashka.impl.classpath, babashka.impl.pods, babashka.impl.fs, babashka.impl.ordered, babashka.nrepl.impl.server, babashka.nrepl.impl.utils, babashka.nrepl.server, babashka.wait, babashka.curl, babashka.pods.impl.resolver, babashka.pods.sci, babashka.pods.impl, babashka.process, babashka.main, babashka.fs, borkdude.deps, aaaa_this_has_to_be_first_because_patches, clj_easy.graal_build_time, borkdude.graal.locking, selmer.node

ericdallo21:09:50

hahah seems huge for bb

ericdallo21:09:09

did you implement that logic of using babashka instead of babashka.impl for example?

ericdallo21:09:25

I don't think it's necessary though

borkdude21:09:55

I need to make one more tweak

borkdude21:09:03

foo.bar__init.class means that foo is the package

borkdude21:09:09

and now I'm using foo.bar which isn't enough

borkdude21:09:35

ok pushed a fix, last time testing with bb before I call it quits for today

borkdude21:09:26

Ah this looks much better:

Registering packages for build time initialization: clojure, rewrite_clj, org, cognitect, sci, io, edamame, flatland, bencode, taoensso, hf, clj_yaml, cheshire, selmer, hiccup, babashka, borkdude, aaaa_this_has_to_be_first_because_patches__init.class, clj_easy

borkdude21:09:38

hmm, org...

borkdude21:09:05

this needs some work ;)

ericdallo21:09:40

hahah, I'll test with clojure-lsp soon

borkdude21:09:11

at least it seems to work with bb now

borkdude21:09:24

but the io and org looks a bit too much ;)

ericdallo21:09:53

well, ATM we are including everything with just the --initialize-at-build-time right?

ericdallo21:09:59

it already looks better :)

ericdallo21:09:11

do you know if that should affect performance/compilation speed somehow?

borkdude21:09:22

no I don't think so

👍 2
borkdude21:09:59

ok works fine over here now

ericdallo21:09:36

great work! I let you know how it works with clojure-lsp

borkdude21:09:23

if you're using cheshire, then you'll also need:

--initialize-at-build-time=com.fasterxml.jackson
since cheshire uses some jackson object at the top level I think

borkdude21:09:40

this can be mitigated by putting it in a delay, but it seems this works fine

borkdude21:09:42

perhaps it's worth a PR

ericdallo21:09:45

thanks, clojure-lsp doesn't use cheshire though, but I image other libs that do things like that would require the same

borkdude22:09:29

I think I understand, my regex is too eager

borkdude22:09:42

(-> nm
        (str/replace #"/.*__init.class$" "")
        (str/replace "/" "."))

borkdude22:09:33

in foo/bar/baz__init it should only replace /baz__init

borkdude22:09:44

perhaps you can make a PR for this while I'm asleep ;)

ericdallo22:09:31

Haha sure, I can take a look

borkdude22:09:03

we can just use string/split

borkdude22:09:34

(but on Windows in the directory thing you should use the proper OS-specific character)

borkdude22:09:34

and also we can exclude certain packages if their prefix is already in the set

borkdude22:09:38

that would also be a nice PR

ericdallo12:09:25

I successfully removed digest from clojure-lsp, but still getting one last issue with java.sql.SQLException :

Using CLibrary: com.oracle.svm.core.posix.linux.libc.GLibC

To see how the classes got initialized, use --trace-class-initialization=java.sql.SQLException
[clojure-lsp:582146]     analysis: 100,076.15 ms,  3.83 GB
Error: Classes that should be initialized at run time got initialized during image building:
 java.sql.SQLException the class was requested to be initialized at run time (from jar:file:///home/greg/dev/clojure-lsp/clojure-lsp.jar!/META-INF/native-image/clojure-lsp/clojure-lsp/native-image.properties with 'java.sql'). To see why java.sql.SQLException got initialized use --trace-class-initialization=java.sql.SQLException

com.oracle.svm.core.util.UserError$UserException: Classes that should be initialized at run time got initialized during image building:
 java.sql.SQLException the class was requested to be initialized at run time (from jar:file:///home/greg/dev/clojure-lsp/clojure-lsp.jar!/META-INF/native-image/clojure-lsp/clojure-lsp/native-image.properties with 'java.sql'). To see why java.sql.SQLException got initialized use --trace-class-initialization=java.sql.SQLException

        at com.oracle.svm.core.util.UserError.abort(UserError.java:68)
        at com.oracle.svm.hosted.classinitialization.ConfigurableClassInitialization.checkDelayedInitialization(ConfigurableClassInitialization.java:555)
        at com.oracle.svm.hosted.classinitialization.ClassInitializationFeature.duringAnalysis(ClassInitializationFeature.java:169)
        at com.oracle.svm.hosted.NativeImageGenerator.lambda$runPointsToAnalysis$12(NativeImageGenerator.java:730)
        at com.oracle.svm.hosted.FeatureHandler.forEachFeature(FeatureHandler.java:71)
        at com.oracle.svm.hosted.NativeImageGenerator.runPointsToAnalysis(NativeImageGenerator.java:730)
        at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:532)
        at com.oracle.svm.hosted.NativeImageGenerator.run(NativeImageGenerator.java:491)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.buildImage(NativeImageGeneratorRunner.java:380)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.build(NativeImageGeneratorRunner.java:543)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.main(NativeImageGeneratorRunner.java:119)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner$JDK9Plus.main(NativeImageGeneratorRunner.java:573)
[clojure-lsp:582146]      [total]: 109,298.94 ms,  3.83 GB
# Printing build artifacts to: /home/greg/dev/clojure-lsp/clojure-lsp.build_artifacts.txt
Error: Image build request failed with exit status 1
com.oracle.svm.driver.NativeImage$NativeImageError: Image build request failed with exit status 1
        at com.oracle.svm.driver.NativeImage.showError(NativeImage.java:1916)
        at com.oracle.svm.driver.NativeImage.build(NativeImage.java:1584)
        at com.oracle.svm.driver.NativeImage.performBuild(NativeImage.java:1545)
        at com.oracle.svm.driver.NativeImage.main(NativeImage.java:1532)

ericdallo12:09:09

Should I initialize it manually on native-image config at build-time or run-time?

borkdude12:09:11

This could very well be because you are using some sql stuff on the top level in your code

borkdude12:09:24

which you should maybe put in a delay

ericdallo12:09:24

oh, let me double check then

ericdallo12:09:41

I don't see any top level sql thing on clojure-lsp.db, maybe it comes from :

[next.jdbc :as jdbc]
   [next.jdbc.result-set :as rs]
?

borkdude12:09:57

you could put on the tracing and see

ericdallo12:09:12

yeah, forgot about that tracing, let me try

ericdallo12:09:59

it seems --initialize-at-build-time=java.sql.SQLException worked, but I'll debug who is doing that

dominicm23:09:23

voidlinux now packages babashka in it's main repo, all built from source. Surprisingly it's built using "mandrel" instead of graal: https://github.com/graalvm/mandrel which is pretty cool

borkdude07:09:05

interesting!

borkdude07:09:17

this might be the work of @U01FQSYHRCY :)

Leah Neukirchen15:09:42

Indeed. 😉 I couldn't get GraalVM to build with musl.

borkdude15:09:21

@U01FQSYHRCY But mandrel doesn't support musl at all right?

Leah Neukirchen11:09:58

needs light patching to support musl as a system libc

borkdude13:09:38

Ah I see, the README said it didn't support musl but nice that it does with light patching!