Skip to content

Commit

Permalink
Make isTraceEnabled calls be computed at build time quarkusio#12938
Browse files Browse the repository at this point in the history
  • Loading branch information
galderz committed Nov 4, 2020
1 parent c9741ea commit 9aaa15b
Show file tree
Hide file tree
Showing 4 changed files with 122 additions and 0 deletions.
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));
}
}
}
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
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.
* The message will only be printed if runtime log level for a given category is <code>TRACE</code>.
*/
@ConfigItem(defaultValue = "false")
public boolean buildTimeTraceEnabled;
}
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;
}

0 comments on commit 9aaa15b

Please sign in to comment.