PrintAnalysisCallTree cause a lot of heap allocation during native image build

[johnaohara]

By default we enabled -H:+PrintAnalysisCallTree for native binary builds. For a simple rest-crud application (https://github.com/johnaohara/rest-http-crud) during a native image build;

1. With -H:+PrintAnalysisCallTree; 47.87GB of objects are allocated to the heap
2. Without ; 36.02GB of objects are allocated on the heap

Disabling this option by default would save us 11.85GB of heap allocations (25.2%) during a native image build for the rest-crud application.

@stuartwdouglas I know that we have historically kept this option enabled by default, but given that it causes so much allocation on the heap, is it worth disabling by default for users building native images?

[johnaohara]

Native image build time (for rest-crud application) also reduced from 103771 ms to 84908 ms (~20% reduction)

[zeeZ]

We shaved 12 minutes off a 15 minute build by disabling this option.

2019-10-18T15:34:43.858328327Z [xxx-runner:24]    classlist:  11,035.77 ms
2019-10-18T15:34:45.343044601Z [xxx-runner:24]        (cap):     975.09 ms
2019-10-18T15:34:46.262863629Z [xxx-runner:24]        setup:   2,397.18 ms
2019-10-18T15:38:19.837367346Z [xxx-runner:24]   (typeflow): 155,318.64 ms
2019-10-18T15:38:19.837497343Z [xxx-runner:24]    (objects):  49,119.68 ms
2019-10-18T15:38:19.837650594Z [xxx-runner:24]   (features):   1,929.46 ms
2019-10-18T15:38:19.837863327Z [xxx-runner:24]     analysis: 213,322.67 ms
2019-10-18T15:47:50.863414370Z Printing call tree to /project/reports/...
2019-10-18T15:50:01.645147897Z Printing list of used classes to /project/reports/...
2019-10-18T15:50:01.877119695Z Printing list of used packages to /project/reports/...
2019-10-18T15:50:10.573867399Z [xxx-runner:24]     (clinit):   1,651.35 ms
2019-10-18T15:50:10.609210111Z [xxx-runner:24]     universe:   8,547.64 ms
2019-10-18T15:50:21.322212545Z [xxx-runner:24]      (parse):  10,540.83 ms
2019-10-18T15:50:32.650969959Z [xxx-runner:24]     (inline):  10,720.39 ms
2019-10-18T15:51:32.588594540Z [xxx-runner:24]    (compile):  59,934.40 ms
2019-10-18T15:51:36.863364396Z [xxx-runner:24]      compile:  86,095.92 ms
2019-10-18T15:51:47.184876474Z [xxx-runner:24]        image:  10,321.05 ms
2019-10-18T15:51:50.126260407Z [xxx-runner:24]        write:   2,940.43 ms
2019-10-18T15:51:50.142856305Z [xxx-runner:24]      [total]: 1,037,813.38 ms

Almost 10 minutes were spent just building the call tree, the other two minutes were spent spewing out a 1 GB text file.

[stuartwdouglas]

Let's get rid of it. The error reporting that was so problematic seems to have improved as graal has matured, so I a think the value of this is questionable now anyway.

…

On Sat, 19 Oct. 2019, 3:13 am Christian, ***@***.***> wrote: We shaved 12 minutes off a 15 minute build by disabling this option. 2019-10-18T15:34:43.858328327Z [xxx-runner:24] classlist: 11,035.77 ms 2019-10-18T15:34:45.343044601Z [xxx-runner:24] (cap): 975.09 ms 2019-10-18T15:34:46.262863629Z [xxx-runner:24] setup: 2,397.18 ms 2019-10-18T15:38:19.837367346Z [xxx-runner:24] (typeflow): 155,318.64 ms 2019-10-18T15:38:19.837497343Z [xxx-runner:24] (objects): 49,119.68 ms 2019-10-18T15:38:19.837650594Z [xxx-runner:24] (features): 1,929.46 ms 2019-10-18T15:38:19.837863327Z [xxx-runner:24] analysis: 213,322.67 ms 2019-10-18T15:47:50.863414370Z Printing call tree to /project/reports/... 2019-10-18T15:50:01.645147897Z Printing list of used classes to /project/reports/... 2019-10-18T15:50:01.877119695Z Printing list of used packages to /project/reports/... 2019-10-18T15:50:10.573867399Z [xxx-runner:24] (clinit): 1,651.35 ms 2019-10-18T15:50:10.609210111Z [xxx-runner:24] universe: 8,547.64 ms 2019-10-18T15:50:21.322212545Z [xxx-runner:24] (parse): 10,540.83 ms 2019-10-18T15:50:32.650969959Z [xxx-runner:24] (inline): 10,720.39 ms 2019-10-18T15:51:32.588594540Z [xxx-runner:24] (compile): 59,934.40 ms 2019-10-18T15:51:36.863364396Z [xxx-runner:24] compile: 86,095.92 ms 2019-10-18T15:51:47.184876474Z [xxx-runner:24] image: 10,321.05 ms 2019-10-18T15:51:50.126260407Z [xxx-runner:24] write: 2,940.43 ms 2019-10-18T15:51:50.142856305Z [xxx-runner:24] [total]: 1,037,813.38 ms Almost 10 minutes were spent just building the call tree, the other two minutes were spent spewing out a 1 GB text file. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2241?email_source=notifications&email_token=AACQG62A7TLEJKUVH2AZPI3QPHOCHA5CNFSM4HIVL5RKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEBU7NEQ#issuecomment-543815314>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACQG64OL5ZO7MM3P3GJIUTQPHOCHANCNFSM4HIVL5RA> .

[johnaohara]

@stuartwdouglas have you worked on this? I was going to open a PR, but won't spend time on it if you have already done so

[stuartwdouglas]

I have not.

[johnaohara]

Current assumption is reports are enabled by default (i.e. disable-reports = false). If we simply make the default to true, we would lose the ability to set -Dnative-image.disable-reports on the command line, and to enable reporting would mean users had to specify a double negative e.g in maven pom <disable-reports>false</disable-reports>. I think the parameter should be modified to "enabled-reports", which would allow us to retain the command line option e.g. -Dnative-image.enable-reports=true, and if users want to define the parameter in their pom <enable-reports>true</enable-reports, but this change could break existing builds by switching semantics. @stuartwdouglas wdyt?

[johnaohara]

#4734 has been merged