Skip to content

Commit

Permalink
Simplify logging using static invocations and bytecode transformation
Browse files Browse the repository at this point in the history
  • Loading branch information
Ladicek committed Jan 25, 2021
1 parent 7ad41c3 commit 01150c9
Show file tree
Hide file tree
Showing 22 changed files with 3,112 additions and 7 deletions.
13 changes: 13 additions & 0 deletions .mvn/extensions.xml
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
<?xml version="1.0" encoding="UTF-8"?>
<extensions>
<extension>
<groupId>org.srcdeps.mvn</groupId>
<artifactId>srcdeps-maven-local-repository</artifactId>
<version>4.0.0</version>
</extension>
<extension>
<groupId>org.srcdeps.mvn</groupId>
<artifactId>srcdeps-maven-enforcer</artifactId>
<version>4.0.0</version>
</extension>
</extensions>
17 changes: 16 additions & 1 deletion bom/application/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@
<bouncycastle.version>1.68</bouncycastle.version>
<bouncycastle.fips.version>1.0.2</bouncycastle.fips.version>
<bouncycastle.tls.fips.version>1.0.11</bouncycastle.tls.fips.version>
<jandex.version>2.2.3.Final</jandex.version>
<jandex.version>2.2.4.Final-SNAPSHOT</jandex.version>
<resteasy.version>4.5.8.SP1</resteasy.version>
<opentracing.version>0.31.0</opentracing.version>
<opentracing-jaxrs.version>0.4.1</opentracing-jaxrs.version>
Expand Down Expand Up @@ -2149,6 +2149,16 @@
<artifactId>quarkus-test-vault</artifactId>
<version>${project.version}</version>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-logging</artifactId>
<version>${project.version}</version>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-logging-deployment</artifactId>
<version>${project.version}</version>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-logging-json</artifactId>
Expand Down Expand Up @@ -3859,6 +3869,11 @@
<artifactId>asm-analysis</artifactId>
<version>${asm.version}</version>
</dependency>
<dependency>
<groupId>org.ow2.asm</groupId>
<artifactId>asm-commons</artifactId>
<version>${asm.version}</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,8 @@ public final class BytecodeTransformerBuildItem extends MultiBuildItem {

final boolean cacheable;

final int classReaderOptions;

public BytecodeTransformerBuildItem(String classToTransform,
BiFunction<String, ClassVisitor, ClassVisitor> visitorFunction) {
this(classToTransform, visitorFunction, null);
Expand All @@ -49,22 +51,23 @@ public BytecodeTransformerBuildItem(boolean eager, String classToTransform,

public BytecodeTransformerBuildItem(boolean eager, String classToTransform,
BiFunction<String, ClassVisitor, ClassVisitor> visitorFunction, boolean cacheable) {
this(eager, classToTransform, visitorFunction, null, cacheable);
this(eager, classToTransform, visitorFunction, null, cacheable, 0);
}

public BytecodeTransformerBuildItem(boolean eager, String classToTransform,
BiFunction<String, ClassVisitor, ClassVisitor> visitorFunction, Set<String> requireConstPoolEntry) {
this(eager, classToTransform, visitorFunction, requireConstPoolEntry, false);
this(eager, classToTransform, visitorFunction, requireConstPoolEntry, false, 0);
}

public BytecodeTransformerBuildItem(boolean eager, String classToTransform,
BiFunction<String, ClassVisitor, ClassVisitor> visitorFunction, Set<String> requireConstPoolEntry,
boolean cacheable) {
boolean cacheable, int classReaderOptions) {
this.eager = eager;
this.classToTransform = classToTransform;
this.visitorFunction = visitorFunction;
this.requireConstPoolEntry = requireConstPoolEntry;
this.cacheable = cacheable;
this.classReaderOptions = classReaderOptions;
}

public String getClassToTransform() {
Expand All @@ -86,4 +89,8 @@ public boolean isEager() {
public boolean isCacheable() {
return cacheable;
}

public int getClassReaderOptions() {
return classReaderOptions;
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -139,6 +139,12 @@ public Collection<AnnotationInstance> getAnnotationsWithRepeatable(DotName annot
return this.index.getAnnotationsWithRepeatable(annotationName, index);
}

@Override
public Collection<ClassInfo> getKnownUsers(DotName className) {
// TODO additionalClasses?
return index.getKnownUsers(className);
}

private void getAllKnownSubClasses(DotName className, Set<ClassInfo> allKnown, Set<DotName> processedClasses) {
final Set<DotName> subClassesToProcess = new HashSet<DotName>();
subClassesToProcess.add(className);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,7 @@ TransformedClassesBuildItem handleClassTransformation(List<BytecodeTransformerBu
Map<String, Set<String>> constScanning = new HashMap<>();
Set<String> eager = new HashSet<>();
Set<String> nonCacheable = new HashSet<>();
Map<String, Integer> classReaderOptions = new HashMap<>();
for (BytecodeTransformerBuildItem i : bytecodeTransformerBuildItems) {
bytecodeTransformers.computeIfAbsent(i.getClassToTransform(), (h) -> new ArrayList<>())
.add(i.getVisitorFunction());
Expand All @@ -75,6 +76,7 @@ TransformedClassesBuildItem handleClassTransformation(List<BytecodeTransformerBu
if (!i.isCacheable()) {
nonCacheable.add(i.getClassToTransform());
}
classReaderOptions.put(i.getClassToTransform(), i.getClassReaderOptions());
}
QuarkusClassLoader cl = (QuarkusClassLoader) Thread.currentThread().getContextClassLoader();
Map<String, Path> transformedToArchive = new ConcurrentHashMap<>();
Expand Down Expand Up @@ -132,7 +134,8 @@ public TransformedClassesBuildItem.TransformedClass call() throws Exception {
for (BiFunction<String, ClassVisitor, ClassVisitor> i : visitors) {
visitor = i.apply(className, visitor);
}
cr.accept(visitor, 0);
int parsingOptions = classReaderOptions.getOrDefault(className, 0);
cr.accept(visitor, parsingOptions);
byte[] data = writer.toByteArray();
if (BootstrapDebug.DEBUG_TRANSFORMED_CLASSES_DIR != null) {
File debugPath = new File(BootstrapDebug.DEBUG_TRANSFORMED_CLASSES_DIR);
Expand Down
70 changes: 70 additions & 0 deletions extensions/logging/deployment/pom.xml
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-logging-parent</artifactId>
<version>999-SNAPSHOT</version>
<relativePath>../pom.xml</relativePath>
</parent>

<artifactId>quarkus-logging-deployment</artifactId>
<name>Quarkus - Logging - Deployment</name>

<dependencies>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-core-deployment</artifactId>
</dependency>
<dependency>
<groupId>org.ow2.asm</groupId>
<artifactId>asm-commons</artifactId>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-logging</artifactId>
</dependency>
<!-- test dependencies -->
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-junit5-internal</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-junit5</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.assertj</groupId>
<artifactId>assertj-core</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-arc-deployment</artifactId>
<scope>test</scope>
</dependency>
</dependencies>

<build>
<plugins>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-compiler-plugin</artifactId>
<configuration>
<annotationProcessorPaths>
<path>
<groupId>io.quarkus</groupId>
<artifactId>quarkus-extension-processor</artifactId>
<version>${project.version}</version>
</path>
</annotationProcessorPaths>
</configuration>
</plugin>
</plugins>
</build>

</project>
Original file line number Diff line number Diff line change
@@ -0,0 +1,169 @@
package io.quarkus.logging.deployment;

import org.jboss.jandex.ClassInfo;
import org.jboss.jandex.DotName;
import org.objectweb.asm.ClassReader;
import org.objectweb.asm.ClassVisitor;
import org.objectweb.asm.MethodVisitor;
import org.objectweb.asm.Opcodes;
import org.objectweb.asm.Type;
import org.objectweb.asm.commons.LocalVariablesSorter;

import io.quarkus.deployment.annotations.BuildProducer;
import io.quarkus.deployment.annotations.BuildStep;
import io.quarkus.deployment.builditem.BytecodeTransformerBuildItem;
import io.quarkus.deployment.builditem.CombinedIndexBuildItem;
import io.quarkus.gizmo.Gizmo;

public class QuarkusLogProcessor {
private static final DotName QUARKUS_LOG_DOTNAME = DotName.createSimple("io.quarkus.logging.Log");

private static final String QUARKUS_LOG_BINARY_NAME = "io/quarkus/logging/Log";

private static final String SYNTHETIC_LOGGER_FIELD_NAME = "quarkusSyntheticLogger";

private static final String JBOSS_LOGGER_BINARY_NAME = "org/jboss/logging/Logger";
private static final String JBOSS_LOGGER_DESCRIPTOR = "L" + JBOSS_LOGGER_BINARY_NAME + ";";
private static final String GET_LOGGER_DESCRIPTOR = "(Ljava/lang/String;)" + JBOSS_LOGGER_DESCRIPTOR;

@BuildStep
public void process(CombinedIndexBuildItem index, BuildProducer<BytecodeTransformerBuildItem> transformers) {
for (ClassInfo clazz : index.getIndex().getKnownUsers(QUARKUS_LOG_DOTNAME)) {
String className = clazz.name().toString();

transformers.produce(new BytecodeTransformerBuildItem(false, className, (ignored, visitor) -> {
return new SynthesiseLogger(visitor, className);
}, null, false, ClassReader.EXPAND_FRAMES));
}
}

private static class SynthesiseLogger extends ClassVisitor {
private final String className;
private final String classNameBinary;

private boolean generatedLoggerFieldInitialization;

public SynthesiseLogger(ClassVisitor visitor, String className) {
super(Gizmo.ASM_API_VERSION, visitor);
this.className = className;
this.classNameBinary = className.replace(".", "/");
}

@Override
public void visit(int version, int access, String name, String signature, String superName, String[] interfaces) {
super.visit(version, access, name, signature, superName, interfaces);

// TODO per ClassVisitor javadoc, this should probably be called a bit later?
super.visitField(Opcodes.ACC_PRIVATE | Opcodes.ACC_STATIC | Opcodes.ACC_FINAL /* | Opcodes.ACC_SYNTHETIC */,
SYNTHETIC_LOGGER_FIELD_NAME, JBOSS_LOGGER_DESCRIPTOR, null, null);
}

@Override
public MethodVisitor visitMethod(int access, String name, String descriptor, String signature, String[] exceptions) {
MethodVisitor visitor = super.visitMethod(access, name, descriptor, signature, exceptions);
if (visitor == null) {
return null;
}

return new LocalVariablesSorter(Gizmo.ASM_API_VERSION, access, descriptor, visitor) {
@Override
public void visitCode() {
if ("<clinit>".equals(name)) {
super.visitLdcInsn(className);
super.visitMethodInsn(Opcodes.INVOKESTATIC, JBOSS_LOGGER_BINARY_NAME, "getLogger",
GET_LOGGER_DESCRIPTOR, false);
super.visitFieldInsn(Opcodes.PUTSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
JBOSS_LOGGER_DESCRIPTOR);
generatedLoggerFieldInitialization = true;
}

super.visitCode();
}

@Override
public void visitMethodInsn(int opcode, String owner, String name, String descriptor, boolean isInterface) {
if (!QUARKUS_LOG_BINARY_NAME.equals(owner)) {
super.visitMethodInsn(opcode, owner, name, descriptor, isInterface);
return;
}

Type[] argTypes = Type.getArgumentTypes(descriptor);
int numArgs = argTypes.length;
int[] locals = null;

boolean directStackManipulation = isDirectStackManipulationPossible(argTypes);

// for 0, 1 or 2 arguments of the logger method, where each only takes 1 stack slot,
// direct stack manipulation is possible
// for 3 or more arguments, or less arguments but at least one taking 2 stack slots,
// we move them from stack to local variables and restore later
if (!directStackManipulation) {
// stack: [arg1 arg2 arg3 arg4] locals: {}
// stack: [arg1 arg2 arg3] locals: {l1 = arg4}
// stack: [arg1 arg2] locals: {l1 = arg4 l2 = arg3}
// stack: [arg1] locals: {l1 = arg4 l2 = arg3 l3 = arg2}
// stack: [] locals: {l1 = arg4 l2 = arg3 l3 = arg2 l4 = arg1}
locals = new int[numArgs];
for (int i = numArgs - 1; i >= 0; i--) {
locals[i] = newLocal(argTypes[i]);
super.visitVarInsn(argTypes[i].getOpcode(Opcodes.ISTORE), locals[i]);
}
}

// stack: [] -> [logger]
super.visitFieldInsn(Opcodes.GETSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
JBOSS_LOGGER_DESCRIPTOR);

if (directStackManipulation) {
if (numArgs == 1) {
// stack: [arg1 logger] -> [logger arg1]
super.visitInsn(Opcodes.SWAP);
} else if (numArgs == 2) {
// stack: [arg1 arg2 logger] -> [logger arg1 arg2 logger]
super.visitInsn(Opcodes.DUP_X2);
// stack: [logger arg1 arg2 logger] -> [logger arg1 arg2]
super.visitInsn(Opcodes.POP);
}
} else {
// stack: [logger] locals: {l1 = arg4 l2 = arg3 l3 = arg2 l4 = arg1}
// stack: [logger arg1] locals: {l1 = arg4 l2 = arg3 l3 = arg2}
// stack: [logger arg1 arg2] locals: {l1 = arg4 l2 = arg3}
// stack: [logger arg1 arg2 arg3] locals: {l1 = arg4}
// stack: [logger arg1 arg2 arg3 arg4] locals: {}
for (int i = 0; i < numArgs; i++) {
super.visitVarInsn(argTypes[i].getOpcode(Opcodes.ILOAD), locals[i]);
}
}

super.visitMethodInsn(Opcodes.INVOKEVIRTUAL, JBOSS_LOGGER_BINARY_NAME, name, descriptor, false);
}

private boolean isDirectStackManipulationPossible(Type[] argTypes) {
return argTypes.length == 0
|| argTypes.length == 1 && argTypes[0].getSize() == 1
|| argTypes.length == 2 && argTypes[0].getSize() == 1 && argTypes[1].getSize() == 1;
}
};
}

@Override
public void visitEnd() {
if (!generatedLoggerFieldInitialization) {
MethodVisitor visitor = super.visitMethod(Opcodes.ACC_STATIC, "<clinit>", "()V", null, null);
visitor.visitCode();
visitor.visitLdcInsn(className);
visitor.visitMethodInsn(Opcodes.INVOKESTATIC, JBOSS_LOGGER_BINARY_NAME, "getLogger",
GET_LOGGER_DESCRIPTOR, false);
visitor.visitFieldInsn(Opcodes.PUTSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
JBOSS_LOGGER_DESCRIPTOR);
visitor.visitInsn(Opcodes.RETURN);
visitor.visitMaxs(1, 0);
visitor.visitEnd();

generatedLoggerFieldInitialization = true;
}

super.visitEnd();
}
}
}
Loading

0 comments on commit 01150c9

Please sign in to comment.