Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Subprocess report generation #286

Merged
merged 38 commits into from
Oct 28, 2020

Conversation

andrewazores
Copy link
Member

@andrewazores andrewazores commented Oct 5, 2020

Fixes #8

Subprocess report generation so that if report requires too much memory, the subprocess can be killed rather than allowing the whole container to be taken down. This can be done by the parent process setting a smaller maximum heap size for the subprocess - currently it just assumes a value of 200M, but some heuristic can be applied here to vary the size according to the container limits. The subprocess is not yet able to connect back to container-jfr itself currently, probably due to some kind of JMX/RMI/SSL misconfiguration.

This definitely increases latency of report generation, but with greatly reduced risk of crashing the whole ContainerJFR instance, so it seems to be a worthwhile tradeoff. Especially since we already have the report caching layer in front of this, so only the first load will be slower due to the subprocess fork/await.

@andrewazores andrewazores force-pushed the subprocess-report branch 3 times, most recently from ac90a8d to fd21a4d Compare October 6, 2020 17:53
@andrewazores
Copy link
Member Author

The generator can connect back to its own container when running in OpenShift, but this still isn't working when using smoketest.sh or generally when running in Podman. Not sure exactly what the problem is but at this point I suspect it's some kind of networking issue. Maybe not worth worrying too much about since it only seems to affect Podman and only when connecting back to ContainerJFR itself, which isn't an important use case. That con is certainly outweighed by the pros here, IMO.

Still needs some cleanup work, then 1) the subprocess max heap size should be determined by some runtime heuristics from the parent ContainerJFR and 2) the subprocess needs some way to be informed of and load the set of report transformers to apply

@andrewazores
Copy link
Member Author

Part 1 probably can't be properly addressed until we can switch to a new base image with JDK 11.0.9+ : https://bugs.openjdk.java.net/browse/JDK-8226575 . Once we are on that base then the OperatingSystemMXBean can tell us how much headroom we have for report generation at the time of the request.

@andrewazores
Copy link
Member Author

Report transformation handling is now implemented. The parent process serializes the set of transformers (as a newline-delimited list of fully-qualified transformer class names) into a file, which the subprocess then reads, deserializes, and recreates all of the transformers by loading the classes from the classpath and instantiating the default no-args constructor. The subprocess then truncates and reuses this file to write out the report contents before exiting.

@andrewazores
Copy link
Member Author

SubprocessReportGenerator needs refactoring and testing. After that, the only outstanding issue will be the subprocess heap size heuristic as point 1 above and in #287, which can probably be handled at a later time since it will be a fairly minor change and is really just an additional enhancement to this patch.

@andrewazores andrewazores force-pushed the subprocess-report branch 3 times, most recently from 8d2d64c to 23f9596 Compare October 13, 2020 20:10
@andrewazores andrewazores requested a review from ebaron October 13, 2020 20:21
@andrewazores andrewazores marked this pull request as ready for review October 13, 2020 20:21
@andrewazores
Copy link
Member Author

SubprocessReportGenerator could probably be split up a bit more with things made non-static for testing, but it's pretty simple stuff it's doing - not sure it's really worth the effort. Other than that I think this is in review-ready shape.

@andrewazores andrewazores changed the title Subprocess report generation [Proof-of-concept] Subprocess report generation Oct 13, 2020
@andrewazores andrewazores requested a review from vic-ma October 14, 2020 16:11
@andrewazores
Copy link
Member Author

Just noticed that this fails integration tests:

[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 6.089 s <<< FAILURE! - in itest.RecordingWorkflowIT
[ERROR] itest.RecordingWorkflowIT.testWorkflow  Time elapsed: 6.075 s  <<< ERROR!
java.util.concurrent.ExecutionException: java.lang.Exception: HTTP 500
	at itest.RecordingWorkflowIT.testWorkflow(RecordingWorkflowIT.java:210)
Caused by: java.lang.Exception: HTTP 500

I'm looking into it.

@andrewazores
Copy link
Member Author

andrewazores commented Oct 15, 2020

Bisection shows the first bad commit appears to be 9f7f93955f9f9438ab9119bc19a79584b0e0428b (ie the last one)

@andrewazores
Copy link
Member Author

Here are the relevant ContainerJFR logs:

[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[[INFO] (127.0.0.1:57614): GET /api/v1/targets/localhost/recordings 200 48ms
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): POST /api/v1/targets/localhost/recordings 201 237ms
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): GET /api/v1/targets/localhost/recordings 200 28ms
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): PATCH /api/v1/targets/localhost/recordings/workflow_itest 200 482ms
TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): GET /api/v1/targets/localhost/recordings 200 30ms
INFO] (127.0.0.1:57614): GET /api/v1/recordings 200 8ms
[[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): GET /api/v1/targets/localhost/recordings 200 46ms
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): GET /api/v1/targets/service:jmx:rmi:%2F%2F%2Fjndi%2Frmi:%2F%2Flocalhost:9091%2Fjmxrmi/recordings/workflow_itest 200 121ms
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[ERROR] io.vertx.ext.web.handler.impl.HttpStatusException: Internal Server Error
Caused by: java.lang.NullPointerException
	at java.base/java.util.Objects.requireNonNull(Objects.java:221)
	at com.redhat.rhjmc.containerjfr.net.ConnectionDescriptor.<init>(ConnectionDescriptor.java:62)
	at com.redhat.rhjmc.containerjfr.net.web.http.AbstractAuthenticatedRequestHandler.getConnectionDescriptorFromContext(AbstractAuthenticatedRequestHandler.java:143)
	at com.redhat.rhjmc.containerjfr.net.web.http.api.v1.TargetRecordingGetHandler.handleRecordingDownloadRequest(TargetRecordingGetHandler.java:129)
	at com.redhat.rhjmc.containerjfr.net.web.http.api.v1.RecordingGetHandler.handleAuthenticated(RecordingGetHandler.java:103)
	at com.redhat.rhjmc.containerjfr.net.web.http.AbstractAuthenticatedRequestHandler.handle(AbstractAuthenticatedRequestHandler.java:82)
	at com.redhat.rhjmc.containerjfr.net.web.http.AbstractAuthenticatedRequestHandler.handle(AbstractAuthenticatedRequestHandler.java:61)
	at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)

[INFO] (127.0.0.1:57614): GET /api/v1/recordings/localhost_workflow_itest_20201015T230837Z.jfr 500 2ms
[TRACE] Locking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[TRACE] Invalidating active report cache for workflow_itest
[INFO] (127.0.0.1:57614): DELETE /api/v1/targets/localhost/recordings/workflow_itest 200 30ms
[TRACE] Unlocking connection service:jmx:rmi:///jndi/rmi://localhost:9091/jmxrmi
[INFO] (127.0.0.1:57614): GET /api/v1/recordings 200 0ms
[TRACE] Invalidating archived report cache for localhost_workflow_itest_20201015T230837Z.jfr
[INFO] (127.0.0.1:57614): DELETE /api/v1/recordings/localhost_workflow_itest_20201015T230837Z.jfr 200 3ms
INFO] (127.0.0.1:57614): GET /api/v1/targets 200 6ms
[INFO] (127.0.0.1:57614): GET /api/v1/targets 200 1ms
[[INFO] (127.0.0.1:57614): GET /api/v1/clienturl 200 1ms
[INFO] Connected remote client 127.0.0.1:57638
[INFO] (127.0.0.1:57638): CMD {"command":"url","args":[]}
[INFO] Disconnected remote client 127.0.0.1:57638
[INFO] (127.0.0.1:57614): GET /api/v1/clienturl 200 0ms
[INFO] Connected remote client 127.0.0.1:57642
[INFO] (127.0.0.1:57642): CMD {"command":"ip","args":[]}
[INFO] Disconnected remote client 127.0.0.1:57642
[INFO] (127.0.0.1:57614): GET /api/v1/clienturl 200 3ms
[INFO] Connected remote client 127.0.0.1:57646
[INFO] (127.0.0.1:57646): CMD {"command":"ping","args":[]}
[INFO] Disconnected remote client 127.0.0.1:57646
[INFO] (127.0.0.1:57614): GET /api/v1/clienturl 200 2ms
[INFO] Connected remote client 127.0.0.1:57650
[INFO] (127.0.0.1:57650): CMD {"command":"hostname","args":[]}
[INFO] Disconnected remote client 127.0.0.1:57650
[INFO] (127.0.0.1:57592): GET /index.html 200 46961ms

@andrewazores
Copy link
Member Author

Figured it out. The handler for archived recordings extends the handler for active recordings, so it ends up creating a ConnectionDescriptor with a null target. So I was overzealous in applying a requireNonNull there. This is an implementation detail to reconsider in the future, but not as part of this PR.

@andrewazores andrewazores force-pushed the subprocess-report branch 2 times, most recently from dfa32dc to fdc3878 Compare October 19, 2020 19:30
@andrewazores
Copy link
Member Author

Since I've added the oom_score_adj handling a few commits back, I don't know if it makes sense anymore to set the max heap size of the subprocess. The subprocess JVM can probably just be allowed to consume as much memory as is available, and it should always be the one OOM-killed if the memory constraints are exceeded while leaving the parent ContainerJFR (which is PID 1 in this PR as well, since the entrypoint execs the Java process). The subprocess is also forcibly destroyed if it spends too much time in processing, so there shouldn't be a concern there either of the subprocess eating all available memory in cases where ContainerJFR is allocated a very large amount of memory to use.

@vic-ma
Copy link
Contributor

vic-ma commented Oct 21, 2020

Is there a good way to test the scenario where the report is too large and causes the process to terminate? Does something like this work?

@@ -288,6 +288,9 @@ class SubprocessReportGenerator {
             Logger.INSTANCE.info(SubprocessReportGenerator.class.getName() + " processing report");
             String report;
             URI uri = new URI(targetId);
+
+            System.exit(ExitStatus.OUT_OF_MEMORY.code);
+
             if ("file".equals(uri.getScheme())) {
                 report = getReportFromArchivedRecording(Paths.get(uri.getPath()), saveFile);
             } else {

In this case, I can see the exception in the logs and in the response body, but the response status code is a 200.

Also, is it a problem that the handler doesn't work for me when I run cjfr as a local process (but it works fine if I just use run.sh)?

Error: Could not find or load main class com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator
Caused by: java.lang.ClassNotFoundException: com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator
[ERROR] com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator$ReportGenerationException: [1] Connection to target JVM failed.
...
[ERROR] java.util.concurrent.ExecutionException: com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator$ReportGenerationException: [1] Connection to target JVM failed.

@andrewazores
Copy link
Member Author

andrewazores commented Oct 21, 2020

Is there a good way to test the scenario where the report is too large and causes the process to terminate? Does something like this work?

@@ -288,6 +288,9 @@ class SubprocessReportGenerator {
             Logger.INSTANCE.info(SubprocessReportGenerator.class.getName() + " processing report");
             String report;
             URI uri = new URI(targetId);
+
+            System.exit(ExitStatus.OUT_OF_MEMORY.code);
+
             if ("file".equals(uri.getScheme())) {
                 report = getReportFromArchivedRecording(Paths.get(uri.getPath()), saveFile);
             } else {

In this case, I can see the exception in the logs and in the response body, but the response status code is a 200.

Yea, you can do that. The other alternative would be to set the --memory flag to some small value in run.sh when the container-jfr container is started, then run a recording for a while with either template=ALL or template=Profiling to generate a large recording, and then try to get a report for it. The closer you can tune the --memory flag to the idle requirements of the containers within the pod, the more quickly the OOM on the subprocess will be triggered.

The 200 response code is intentional, at least for now. The code will be 200 but the response body should be some error message, rather than an HTML report. This is because of how the caching system works - if I throw an exception from the method that produces the report string then that result is not cached, and so subsequent requests will retry the same generation. Reports tend to increase in size with time, or at least stay the same size, so if a previous report generation has failed, then a retry is likely to fail as well, so the failure should be cached.

Also, is it a problem that the handler doesn't work for me when I run cjfr as a local process (but it works fine if I just use run.sh)?

I don't think that really matters. We're targeting OpenShift/Kubernetes first, then general containerized workloads, and the local JVM process case isn't really an intended use case. We're working toward packaging and distribution of an Operator and container images but nothing like an RPM where the local process scenario would need to be supported.

Error: Could not find or load main class com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator
Caused by: java.lang.ClassNotFoundException: com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator
[ERROR] com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator$ReportGenerationException: [1] Connection to target JVM failed.
...
[ERROR] java.util.concurrent.ExecutionException: com.redhat.rhjmc.containerjfr.net.internal.reports.SubprocessReportGenerator$ReportGenerationException: [1] Connection to target JVM failed.

As I documented above however, even when using run.sh/smoketest.sh, the subprocess is unable to connect back to its own ContainerJFR container for report generation. When I test this using CRC however it works as expected, so I believe the root problem here is to do with how networking is set up with run.sh. I didn't spend much effort trying to debug that since smoketest.sh also exists and provides a second target to connect to anyway.

vic-ma
vic-ma previously approved these changes Oct 21, 2020
Open target connection and copy recording stream to file, then close target connection before proceeding with report generation. This holds the target connection open for the least time possible
@andrewazores
Copy link
Member Author

Okay, I'm done tinkering with this now. Any further changes beyond review adjustments will be made in separate follow-up PRs.

@vic-ma
Copy link
Contributor

vic-ma commented Oct 28, 2020

This isn't only on the recent commits, but I noticed that for archived recordings, the first time I request the report, I will see "Not found" in the body, but for all subsequent times, I don't see anything in the body. Is this an issue?

Also, in general, after the first time I request an archived recording's report, I don't see a log for the GET request. For getting a targeted recording's report, I do see the log each time.

@andrewazores
Copy link
Member Author

Hmm. I'm not able to reproduce the Not Found you describe, either with the web-client or manually with curl. Could you provide step-by-step instructions to reproduce it and a screenshot of what you see?

For the missing request logs, I think this comes from the context.response().sendFile used - this causes Vertx to ask the underlying OS to write the files to the network directly, without passing it through our application, so we don't end up logging anything. If you look in WebServer, where this logging handler is installed (line ~188), it only writes those log lines after the response is written (so that the time to service the request can also be logged). If the response wasn't written by our application then this handler isn't called. This is the same as when your browser requests web-client assets - you can see requests for things like GET /api/v1/grafana_dashboard_url but not things like GET /index.html or GET /somefont.ttf, because the latter two are files and served directly.

@vic-ma
Copy link
Contributor

vic-ma commented Oct 28, 2020

To run cjfr, I did CONTAINER_JFR_REPORT_GENERATION_MAX_HEAP=5 sh smoketest.sh.

Then,

curl --data "recordingName=foo&duration=5&events=template=ALL" localhost:8181/api/v1/targets/localhost/recordings

curl -X PATCH --data "SAVE" http://localhost:8181/api/v1/targets/localhost/recordings/foo

curl localhost:8181/api/v1/reports/localhost_foo_20201028T170646Z.jfr

In the screenshot, at the end, I also tried using the reportUrl from the recording descriptor.

subprocess

@andrewazores
Copy link
Member Author

Ah, this might be specifically to do with the OOM handling then - I missed that part. Let me try it again with that.

@andrewazores
Copy link
Member Author

Should be fixed now. I'm still not too happy with the fact that these errors are reported along with a 200 status code, but that's going to be a heavier refactoring that I'll do as a follow-up later on. It'll also need support on the web-client side, so I think it's way out of scope of this PR.

Write error message to cached file and serve this to clients. This brings the behaviour in line with the failure handling for active recordings.
@andrewazores andrewazores merged commit 29eb38e into cryostatio:main Oct 28, 2020
@andrewazores andrewazores deleted the subprocess-report branch October 28, 2020 18:28
andrewazores added a commit to andrewazores/cryostat that referenced this pull request Oct 28, 2020
* Proof-of-concept

Subprocess report generation so that if report requires too much memory,
the subprocess can be killed rather than allowing the whole container to
be taken down. This can be done by the parent process setting a smaller
maximum heap size for the subprocess (not yet configurable). The
subprocess is not able to connect back to container-jfr itself
currently.

* Remove redundant parent process work performed by subprocess

* Limit maximum subprocess generation time

* Use Logger rather than raw System.out/err

* Spotless format

* Subprocess doesn't need to listen for incoming JMX connections

* fixup! Use Logger rather than raw System.out/err

* Better handling of subprocess timeout

* Update TODOS

* Write transformer set to file used for writing report

* Apply spotless formatting

* Refactor to use Builder with configurable env

* Pass optional credentials via env vars

* Simplify jvm arg list creation

* Use EpsilonGC for subprocess

* Add TODO

* Refactor cleanup

* Process archived recording reports in subprocess

* Fix tests

* Get truststore values from env, not filesystem

* Make /truststore dir configurable

* Use existing FileSystem local var

* Return Future and clean up clones

Return Future to allow better async handling of long-running subprocess report generation. Close recording streams when subprocess successfully generates reports to avoid dangling clone recordings, and if subprocess exits due to OOM, clean up dangling clones from parent process

* Refactor, add nonnull assertions, add tests

* Set subprocess OOM score adjustment if supported

* Allow null targetIds

This may be used in cases where a ConnectionDescriptor is used to represent contextual Credentials from an HTTP request for a non-target-oriented action or resource

* Address spotbugs violations

* Report target connection failure more accurately

* Remove subprocess max heap size

* Log elapsed subprocess run time

* Revert "Remove subprocess max heap size"

This reverts commit fb8252a.

If the subprocess does not exit due to exceeding the specified heap size
then the exit status will not be set as expected, and the parent process
will not know why the subprocess failed

* Ensure subprocess is terminated

* Add env var to configure subprocess max heap

* Document possible error message response on report generation

* Document CONTAINER_JFR_REPORT_GENERATION_MAX_HEAP

* Set subprocess timeout equal to HTTP timeout

* Copy recording to file temporarily

Open target connection and copy recording stream to file, then close target connection before proceeding with report generation. This holds the target connection open for the least time possible

* Improve archived report generation failure handling

Write error message to cached file and serve this to clients. This brings the behaviour in line with the failure handling for active recordings.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

HTML Reports generation (GET /reports/foo) can cause OOM
2 participants