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.

Sign up for GitHub

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

Make isTraceEnabled calls be computed at build time #12938 #13102

Closed
wants to merge 1 commit into from
Closed

Make isTraceEnabled calls be computed at build time #12938 #13102

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
84 changes: 84 additions & 0 deletions core/deployment/src/main/java/io/quarkus/deployment/logging/LoggingResourceProcessor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,11 +11,13 @@
import org.jboss.logmanager.EmbeddedConfigurator;

import io.quarkus.bootstrap.logging.InitialConfigurator;
import io.quarkus.deployment.GeneratedClassGizmoAdaptor;
import io.quarkus.deployment.annotations.BuildProducer;
import io.quarkus.deployment.annotations.BuildStep;
import io.quarkus.deployment.annotations.ExecutionTime;
import io.quarkus.deployment.annotations.Record;
import io.quarkus.deployment.builditem.ConsoleFormatterBannerBuildItem;
import io.quarkus.deployment.builditem.GeneratedClassBuildItem;
import io.quarkus.deployment.builditem.LogCategoryBuildItem;
import io.quarkus.deployment.builditem.LogConsoleFormatBuildItem;
import io.quarkus.deployment.builditem.LogHandlerBuildItem;
Expand All @@ -27,6 +29,16 @@
import io.quarkus.deployment.builditem.nativeimage.ServiceProviderBuildItem;
import io.quarkus.deployment.metrics.MetricsCapabilityBuildItem;
import io.quarkus.deployment.metrics.MetricsFactoryConsumerBuildItem;
import io.quarkus.gizmo.AnnotationCreator;
import io.quarkus.gizmo.BranchResult;
import io.quarkus.gizmo.BytecodeCreator;
import io.quarkus.gizmo.ClassCreator;
import io.quarkus.gizmo.ClassOutput;
import io.quarkus.gizmo.FieldCreator;
import io.quarkus.gizmo.FieldDescriptor;
import io.quarkus.gizmo.MethodCreator;
import io.quarkus.gizmo.MethodDescriptor;
import io.quarkus.gizmo.ResultHandle;
import io.quarkus.runtime.RuntimeValue;
import io.quarkus.runtime.logging.LogBuildTimeConfig;
import io.quarkus.runtime.logging.LogConfig;
Expand Down Expand Up @@ -140,4 +152,76 @@ void registerMetrics(LogMetricsHandlerRecorder recorder, LogBuildTimeConfig log,
logHandler.produce(new LogHandlerBuildItem(recorder.getLogHandler()));
}
}

@BuildStep
void setUpTraceLogging(LogBuildTimeConfig log,
final BuildProducer<GeneratedClassBuildItem> generatedTraceLogger) {
final List<String> traceCategories = log.categories.entrySet().stream()
.filter(entry -> entry.getValue().buildTimeTraceEnabled)
.map(Map.Entry::getKey)
.collect(Collectors.toList());

ClassOutput output = new GeneratedClassGizmoAdaptor(generatedTraceLogger, false);
if (traceCategories.isEmpty()) {
generateNoTraceLogger(output);
} else {
generateTraceLogger(traceCategories, output);
}
}

private void generateNoTraceLogger(ClassOutput output) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className("Target_org_jboss_logging_Logger")
.classOutput(output).build()) {

AnnotationCreator targetClass = cc.addAnnotation("com.oracle.svm.core.annotate.TargetClass");
targetClass.addValue("className", "org.jboss.logging.Logger");

MethodCreator isTraceEnabled = cc.getMethodCreator("isTraceEnabled", boolean.class);
isTraceEnabled.addAnnotation("com.oracle.svm.core.annotate.Substitute");
isTraceEnabled.addAnnotation("org.graalvm.compiler.api.replacements.Fold");

isTraceEnabled.returnValue(isTraceEnabled.load(false));
}
}

private void generateTraceLogger(List<String> categories, ClassOutput output) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className("Target_org_jboss_logging_Logger")
.classOutput(output).build()) {

AnnotationCreator targetClass = cc.addAnnotation("com.oracle.svm.core.annotate.TargetClass");
targetClass.addValue("className", "org.jboss.logging.Logger");

final FieldCreator nameAlias = cc.getFieldCreator("name", String.class);
nameAlias.addAnnotation("com.oracle.svm.core.annotate.Alias");

MethodCreator isTraceEnabled = cc.getMethodCreator("isTraceEnabled", boolean.class);
isTraceEnabled.addAnnotation("com.oracle.svm.core.annotate.Substitute");
isTraceEnabled.addAnnotation("org.graalvm.compiler.api.replacements.Fold");

final FieldDescriptor nameAliasField = nameAlias.getFieldDescriptor();
BytecodeCreator current = isTraceEnabled;
for (String category : categories) {
ResultHandle equalsResult = current.invokeVirtualMethod(
MethodDescriptor.ofMethod(Object.class, "equals", boolean.class, Object.class),
current.readInstanceField(nameAliasField, current.getThis()), current.load(category));

BranchResult equalsBranch = current.ifTrue(equalsResult);
try (BytecodeCreator false1 = equalsBranch.falseBranch()) {
ResultHandle startsWithResult = false1.invokeVirtualMethod(
MethodDescriptor.ofMethod(String.class, "startsWith", boolean.class, String.class),
false1.readInstanceField(nameAliasField, false1.getThis()), false1.load(category));

BranchResult startsWithBranch = false1.ifTrue(startsWithResult);
startsWithBranch.trueBranch().returnValue(startsWithBranch.trueBranch().load(true));
current = startsWithBranch.falseBranch();
}

equalsBranch.trueBranch().returnValue(equalsBranch.trueBranch().load(true));
}

current.returnValue(current.load(false));
}
}
}
1 change: 1 addition & 0 deletions core/deployment/src/main/java/io/quarkus/deployment/pkg/steps/NativeImageBuildStep.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -172,6 +172,7 @@ public NativeImageBuildItem build(NativeConfig nativeConfig, NativeImageSourceJa
command.add(
"-H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy$BySpaceAndTime"); //the default collection policy results in full GC's 50% of the time
command.add("-H:+JNI");
command.add("-H:+AllowFoldMethods");
command.add("-jar");
command.add(runnerJarName);

Expand Down
23 changes: 23 additions & 0 deletions core/runtime/src/main/java/io/quarkus/runtime/logging/CategoryBuildTimeConfig.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
package io.quarkus.runtime.logging;

import io.quarkus.runtime.annotations.ConfigGroup;
import io.quarkus.runtime.annotations.ConfigItem;

@ConfigGroup
public class CategoryBuildTimeConfig {
/**
* Specifies whether <code>isTraceEnabled</code> for a given category will return true or false for a given category.
* This check is computed at build time to provide better hints on code paths that won't be used at runtime.
*
* It's common to see <code>isTraceEnabled</code> calls in sections that include building complex or expensive messages.
* By using <code>isTraceEnabled</code> checks, users can double check that trace enabled before computing such a message.
* Otherwise, complex messages could be constructed but then not used by the logging library if the runtime log level is not trace.
* This build time option controls whether `isTraceEnabled` returns true or false at build time and makes that a constant at runtime,
* irrespective of the runtime log level.
*
* Calls to <code>trace()</code> not preceded by <code>isTraceEnabled</code> are still governed by the runtime log level.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a bit odd in terms of semantics, no? Wouldn't it be far easier for users to understand this feature if the focus was about the trace cathegory as a whole not being something which can be controlled at runtime?

I love the potential of your patch, but in the current shape I'm a bit concerned about it exposing much complexity.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, it feels a bit odd. I already hinted at this issue here, but @dmlloyd opposed the idea that build time trace configuration should delete all trace calls.

To make this a fully build time feature, aside of what I did in this PR, you'd need to remove quarkus.log.category.<...>.level=TRACE option, meaning the ability to set TRACE as a runtime log level.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that as @dmlloyd said, an option can only either be build time or runtime.

Copy link
Member

@Sanne Sanne Nov 4, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To make this a fully build time feature, aside of what I did in this PR, you'd need to remove quarkus.log.category.<...>.level=TRACE option, meaning the ability to set TRACE as a runtime log level.

Right, I can see how people would find that odd as well. But personally I think that would be better: this kinda needs a re-definition of a Level to be special.

Ideally the format of configuration could be more specific; allowing the user to choose which runtime configuration elements are made available via an enumeration - I proposed this on the list in the past.

My past proposal was expressed in the area of databases; so in the build time configuration one could, for example, leave MySQL out:

supported_databases={H2,Oracle,PostgreSQL}

then at runtime one has to choose ONE among the enumeration.

Similarly for log levels one could have

< >.level={TRACE,DEBUG,INFO}

or choose

< >.level={DEBUG,INFO}

Which would leave the TRACE option out, exluding it from the valid runtime options and therefore folding it as "false" - consistently in all circumstances.

IMO it has the following benefits:

  1. it's clear what the end user is opting for
  2. people who prefer having more options at runtime can have their way if they want to
  3. Clean, precise separation of build-time vs runtime configuration

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We had effectively this feature in the min-level configuration. Filtering out arbitrary levels doesn't seem as specifically useful as setting a single bound (and might lead to some confusion). It certainly would be more complex to implement.

Copy link
Member Author

@galderz galderz Nov 9, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@dmlloyd raises a valid point here. Although it sounds useful, it also opens up to some potential misuse, e.g. what if the user sets TRACE,WARN, do you really only want TRACE and WARN and not DEBUG, INFO? If you want to handle ranges, you could add support for .. as an option.

min-level might make more sense, from level X upward. Why was that removed? Was the name confusing? Do you need the flexibility of the enumeration?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree, min-level looks good. I don't know why it was removed.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looking at LogConfig, min-level seemed to be a runtime option. It got deprecated in #10672, but at first glance I don't see specific reasons on why it got deprecated.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It was a build time option originally. It was removed because nobody used it or showed much interest in it.

Copy link
Member Author

@galderz galderz Nov 10, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm working on an update to the PR.

* The message will only be printed if runtime log level for a given category is <code>TRACE</code>.
*/
@ConfigItem(defaultValue = "false")
public boolean buildTimeTraceEnabled;
}
14 changes: 14 additions & 0 deletions core/runtime/src/main/java/io/quarkus/runtime/logging/LogBuildTimeConfig.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,8 @@
package io.quarkus.runtime.logging;

import java.util.Map;

import io.quarkus.runtime.annotations.ConfigDocSection;
import io.quarkus.runtime.annotations.ConfigItem;
import io.quarkus.runtime.annotations.ConfigPhase;
import io.quarkus.runtime.annotations.ConfigRoot;
Expand All @@ -12,4 +15,15 @@ public class LogBuildTimeConfig {
*/
@ConfigItem(name = "metrics.enabled", defaultValue = "false")
public boolean metricsEnabled;

/**
* Logging categories.
* <p>
* Logging is done on a per-category basis. Each category can be independently configured.
* A configuration which applies to a category will also apply to all sub-categories of that category,
* unless there is a more specific matching sub-category configuration.
*/
@ConfigItem(name = "category")
@ConfigDocSection
public Map<String, CategoryBuildTimeConfig> categories;
}