Skip to content

Commit

Permalink
Add build-time min-level logging option #12938
Browse files Browse the repository at this point in the history
* It enables log levels below that to be folded in native.
* Runtime min-level has been removed (was deprecated already).
  • Loading branch information
galderz authored and gsmet committed Jan 4, 2021
1 parent 75510b1 commit f5c4cad
Show file tree
Hide file tree
Showing 72 changed files with 1,458 additions and 17 deletions.
2 changes: 1 addition & 1 deletion .github/native-tests.json
Original file line number Diff line number Diff line change
Expand Up @@ -95,7 +95,7 @@
{
"category": "Misc1",
"timeout": 65,
"test-modules": "maven jackson jsonb jsch jgit quartz qute consul-config"
"test-modules": "maven jackson jsonb jsch jgit quartz qute consul-config logging-min-level-unset logging-min-level-set"
},
{
"category": "Misc2",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,19 +3,24 @@
import java.util.List;
import java.util.Map;
import java.util.Optional;
import java.util.function.BiFunction;
import java.util.function.Consumer;
import java.util.function.Supplier;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.stream.Collectors;

import org.jboss.logmanager.EmbeddedConfigurator;
import org.objectweb.asm.Opcodes;

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,14 +32,35 @@
import io.quarkus.deployment.builditem.nativeimage.ServiceProviderBuildItem;
import io.quarkus.deployment.metrics.MetricsCapabilityBuildItem;
import io.quarkus.deployment.metrics.MetricsFactoryConsumerBuildItem;
import io.quarkus.deployment.pkg.steps.NativeBuild;
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.CategoryBuildTimeConfig;
import io.quarkus.runtime.logging.LogBuildTimeConfig;
import io.quarkus.runtime.logging.LogConfig;
import io.quarkus.runtime.logging.LogMetricsHandlerRecorder;
import io.quarkus.runtime.logging.LoggingSetupRecorder;

public final class LoggingResourceProcessor {

private static final String LOGMANAGER_LOGGER_CLASS_NAME = "io.quarkus.runtime.generated.Target_org_jboss_logmanager_Logger";
private static final String LOGGING_LOGGER_CLASS_NAME = "io.quarkus.runtime.generated.Target_org_jboss_logging_Logger";
private static final String LOGGER_NODE_CLASS_NAME = "io.quarkus.runtime.generated.Target_org_jboss_logmanager_LoggerNode";

private static final String MIN_LEVEL_COMPUTE_CLASS_NAME = "io.quarkus.runtime.generated.MinLevelCompute";
private static final MethodDescriptor IS_MIN_LEVEL_ENABLED = MethodDescriptor.ofMethod(MIN_LEVEL_COMPUTE_CLASS_NAME,
"isMinLevelEnabled",
boolean.class, int.class, String.class);

@BuildStep
void setupLogFilters(BuildProducer<LogCleanupFilterBuildItem> filters) {
filters.produce(new LogCleanupFilterBuildItem("org.jboss.threads", "JBoss Threads version"));
Expand Down Expand Up @@ -93,7 +119,7 @@ void miscSetup(

@BuildStep
@Record(ExecutionTime.RUNTIME_INIT)
LoggingSetupBuildItem setupLoggingRuntimeInit(LoggingSetupRecorder recorder, LogConfig log,
LoggingSetupBuildItem setupLoggingRuntimeInit(LoggingSetupRecorder recorder, LogConfig log, LogBuildTimeConfig buildLog,
List<LogHandlerBuildItem> handlerBuildItems,
List<NamedLogHandlersBuildItem> namedHandlerBuildItems, List<LogConsoleFormatBuildItem> consoleFormatItems,
Optional<ConsoleFormatterBannerBuildItem> possibleBannerBuildItem) {
Expand All @@ -111,7 +137,7 @@ LoggingSetupBuildItem setupLoggingRuntimeInit(LoggingSetupRecorder recorder, Log
if (bannerBuildItem != null) {
possibleSupplier = bannerBuildItem.getBannerSupplier();
}
recorder.initializeLogging(log, handlers, namedHandlers,
recorder.initializeLogging(log, buildLog, handlers, namedHandlers,
consoleFormatItems.stream().map(LogConsoleFormatBuildItem::getFormatterValue).collect(Collectors.toList()),
possibleSupplier);
return new LoggingSetupBuildItem();
Expand Down Expand Up @@ -140,4 +166,182 @@ void registerMetrics(LogMetricsHandlerRecorder recorder, LogBuildTimeConfig log,
logHandler.produce(new LogHandlerBuildItem(recorder.getLogHandler()));
}
}

@BuildStep(onlyIf = NativeBuild.class)
void setUpMinLevelLogging(LogBuildTimeConfig log,
final BuildProducer<GeneratedClassBuildItem> generatedTraceLogger) {
ClassOutput output = new GeneratedClassGizmoAdaptor(generatedTraceLogger, false);
if (log.categories.isEmpty() || allMinLevelInfoOrHigher(log.categories)) {
generateDefaultLoggers(output);
} else {
generateCategoryMinLevelLoggers(log.categories, log.minLevel, output);
}
}

private static boolean allMinLevelInfoOrHigher(Map<String, CategoryBuildTimeConfig> categories) {
return categories.values().stream()
.allMatch(categoryConfig -> categoryConfig.minLevel.getLevel().intValue() >= org.jboss.logmanager.Level.INFO
.intValue());
}

private static void generateDefaultLoggers(ClassOutput output) {
generateDefaultLoggingLogger(output);
generateDefaultLoggerNode(output);
generateLogManagerLogger(output, LoggingResourceProcessor::generateMinLevelDefault);
}

private static void generateCategoryMinLevelLoggers(Map<String, CategoryBuildTimeConfig> categories, Level minLevel,
ClassOutput output) {
generateMinLevelCompute(categories, minLevel.toString(), output);
generateDefaultLoggerNode(output);
generateLogManagerLogger(output, LoggingResourceProcessor::generateMinLevelCheckCategory);
}

private static BranchResult generateMinLevelCheckCategory(MethodCreator method, FieldDescriptor nameAliasDescriptor) {
final ResultHandle levelIntValue = getParamLevelIntValue(method);
final ResultHandle nameAlias = method.readInstanceField(nameAliasDescriptor, method.getThis());
return method.ifTrue(method.invokeStaticMethod(IS_MIN_LEVEL_ENABLED, levelIntValue, nameAlias));
}

private static void generateMinLevelCompute(Map<String, CategoryBuildTimeConfig> categories, String defaultMinLevelName,
ClassOutput output) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className(MIN_LEVEL_COMPUTE_CLASS_NAME)
.classOutput(output).build()) {

try (MethodCreator mc = cc.getMethodCreator(IS_MIN_LEVEL_ENABLED)) {
mc.setModifiers(Opcodes.ACC_STATIC);

final ResultHandle level = mc.getMethodParam(0);
final ResultHandle name = mc.getMethodParam(1);

BytecodeCreator current = mc;
for (Map.Entry<String, CategoryBuildTimeConfig> entry : categories.entrySet()) {
final String category = entry.getKey();
final int categoryLevelIntValue = entry.getValue().minLevel.getLevel().intValue();

ResultHandle equalsResult = current.invokeVirtualMethod(
MethodDescriptor.ofMethod(Object.class, "equals", boolean.class, Object.class),
name, 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),
name, false1.load(category));

BranchResult startsWithBranch = false1.ifTrue(startsWithResult);

final BytecodeCreator startsWithTrue = startsWithBranch.trueBranch();
final BranchResult levelCompareBranch = startsWithTrue.ifIntegerGreaterEqual(level,
startsWithTrue.load(categoryLevelIntValue));
levelCompareBranch.trueBranch().returnValue(levelCompareBranch.trueBranch().load(true));
levelCompareBranch.falseBranch().returnValue(levelCompareBranch.falseBranch().load(false));

current = startsWithBranch.falseBranch();
}

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

final ResultHandle infoLevelIntValue = getLogManagerLevelIntValue(defaultMinLevelName, current);
final BranchResult isInfoOrHigherBranch = current.ifIntegerGreaterEqual(level, infoLevelIntValue);
isInfoOrHigherBranch.trueBranch().returnValue(isInfoOrHigherBranch.trueBranch().load(true));
isInfoOrHigherBranch.falseBranch().returnValue(isInfoOrHigherBranch.falseBranch().load(false));
}
}
}

private static void generateDefaultLoggerNode(ClassOutput output) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className(LOGGER_NODE_CLASS_NAME)
.classOutput(output).build()) {

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

final MethodCreator isLoggableLevelMethod = cc.getMethodCreator("isLoggableLevel", boolean.class, int.class);
isLoggableLevelMethod.addAnnotation("com.oracle.svm.core.annotate.Alias");
isLoggableLevelMethod.returnValue(isLoggableLevelMethod.load(false));
}
}

private static void generateLogManagerLogger(ClassOutput output,
BiFunction<MethodCreator, FieldDescriptor, BranchResult> isMinLevelEnabledFunction) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className(LOGMANAGER_LOGGER_CLASS_NAME)
.classOutput(output).build()) {

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

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

FieldCreator loggerNodeAlias = cc.getFieldCreator("loggerNode", LOGGER_NODE_CLASS_NAME);
loggerNodeAlias.addAnnotation("com.oracle.svm.core.annotate.Alias");

final MethodCreator isLoggableMethod = cc.getMethodCreator("isLoggable", boolean.class,
java.util.logging.Level.class);
isLoggableMethod.addAnnotation("com.oracle.svm.core.annotate.Substitute");

final ResultHandle levelIntValue = getParamLevelIntValue(isLoggableMethod);

final BranchResult levelBranch = isMinLevelEnabledFunction.apply(isLoggableMethod, nameAlias.getFieldDescriptor());

final BytecodeCreator levelTrue = levelBranch.trueBranch();
levelTrue.returnValue(
levelTrue.invokeVirtualMethod(
MethodDescriptor.ofMethod(LOGGER_NODE_CLASS_NAME, "isLoggableLevel", boolean.class, int.class),
levelTrue.readInstanceField(loggerNodeAlias.getFieldDescriptor(), levelTrue.getThis()),
levelIntValue));

final BytecodeCreator levelFalse = levelBranch.falseBranch();
levelFalse.returnValue(levelFalse.load(false));
}
}

private static ResultHandle getParamLevelIntValue(MethodCreator method) {
final ResultHandle level = method.getMethodParam(0);
return method
.invokeVirtualMethod(MethodDescriptor.ofMethod(Level.class, "intValue", int.class), level);
}

private static BranchResult generateMinLevelDefault(MethodCreator method, FieldDescriptor nameAliasDescriptor) {
final ResultHandle levelIntValue = getParamLevelIntValue(method);
final ResultHandle infoLevelIntValue = getLogManagerLevelIntValue("INFO", method);
return method.ifIntegerGreaterEqual(levelIntValue, infoLevelIntValue);
}

private static ResultHandle getLogManagerLevelIntValue(String levelName, BytecodeCreator method) {
final ResultHandle infoLevel = method.readStaticField(
FieldDescriptor.of(org.jboss.logmanager.Level.class, levelName, org.jboss.logmanager.Level.class));
return method
.invokeVirtualMethod(MethodDescriptor.ofMethod(Level.class, "intValue", int.class), infoLevel);
}

private static void generateDefaultLoggingLogger(ClassOutput output) {
try (ClassCreator cc = ClassCreator.builder().setFinal(true)
.className(LOGGING_LOGGER_CLASS_NAME)
.classOutput(output).build()) {

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

// Constant fold these methods to return false,
// since the build time log level is above this level.
generateFalseFoldMethod("isTraceEnabled", cc);
generateFalseFoldMethod("isDebugEnabled", cc);
}
}

/**
* Generates a method that is constant-folded to always return false.
*/
private static void generateFalseFoldMethod(String name, ClassCreator cc) {
MethodCreator method = cc.getMethodCreator(name, boolean.class);
method.addAnnotation("com.oracle.svm.core.annotate.Substitute");
method.addAnnotation("org.graalvm.compiler.api.replacements.Fold");
method.returnValue(method.load(false));
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -168,6 +168,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,22 @@
package io.quarkus.runtime.logging;

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

@ConfigGroup
public class CategoryBuildTimeConfig {
/**
* The minimum log level for this category.
* By default all categories are configured with <code>INFO</code> minimum level.
*
* To get runtime logging below <code>INFO</code>, e.g. <code>DEBUG</code> or <code>TRACE</code>,
* the minimum level has to be adjusted at build time, the right log level needs to be provided at runtime.
*
* As an example, to get <code>TRACE</code> logging,
* minimum level needs to be at <code>TRACE</code> and the runtime log level needs to match that.
* To get <code>DEBUG</code> logging,
* minimum level needs to be set at <code>DEBUG</code> or <code>TRACE</code> (as well as runtime log level).
*/
@ConfigItem(defaultValue = "inherit")
public InheritableLevel minLevel;
}
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,10 @@
public class CategoryConfig {

/**
* The log level level for this category
* The log level for this category.
*
* Note that to get log levels below <code>INFO</code>,
* the minimum level build time configuration option needs to be adjusted as well.
*/
@ConfigItem(defaultValue = "inherit")
InheritableLevel level;
Expand Down
Original file line number Diff line number Diff line change
@@ -1,5 +1,9 @@
package io.quarkus.runtime.logging;

import java.util.Map;
import java.util.logging.Level;

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 +16,21 @@ public class LogBuildTimeConfig {
*/
@ConfigItem(name = "metrics.enabled", defaultValue = "false")
public boolean metricsEnabled;

/**
* The default minimum log level.
*/
@ConfigItem(defaultValue = "INFO")
public Level minLevel;

/**
* Minimum 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;
}
Original file line number Diff line number Diff line change
Expand Up @@ -33,15 +33,6 @@ public final class LogConfig {
@ConfigItem(defaultValue = "INFO")
public Level level;

/**
* The default minimum log level
*
* @deprecated this functionality was never implemented, it may be deleted or implemented in a future release.
*/
@ConfigItem(defaultValue = "INFO")
@Deprecated
public Level minLevel;

/**
* Console logging.
* <p>
Expand Down
Loading

0 comments on commit f5c4cad

Please sign in to comment.