Skip to content
Permalink
Browse files
8247320: JFR: Reduce logging overhead
Reviewed-by: mgronlun
  • Loading branch information
egahlin committed Jun 10, 2020
1 parent 7e3d4f8 commit 65c461ed747bb7a72ac754589178774789ebca1c
Showing 12 changed files with 68 additions and 40 deletions.
@@ -187,15 +187,19 @@ public static FlightRecorder getFlightRecorder() throws IllegalStateException, S
// before initialization is done
initialized = true;
Logger.log(JFR, INFO, "Flight Recorder initialized");
Logger.log(JFR, DEBUG, "maxchunksize: " + Options.getMaxChunkSize()+ " bytes");
Logger.log(JFR, DEBUG, "memorysize: " + Options.getMemorySize()+ " bytes");
Logger.log(JFR, DEBUG, "globalbuffersize: " + Options.getGlobalBufferSize()+ " bytes");
Logger.log(JFR, DEBUG, "globalbuffercount: " + Options.getGlobalBufferCount());
Logger.log(JFR, DEBUG, "dumppath: " + Options.getDumpPath());
Logger.log(JFR, DEBUG, "samplethreads: " + Options.getSampleThreads());
Logger.log(JFR, DEBUG, "stackdepth: " + Options.getStackDepth());
Logger.log(JFR, DEBUG, "threadbuffersize: " + Options.getThreadBufferSize());
Logger.log(JFR, LogLevel.INFO, "Repository base directory: " + Repository.getRepository().getBaseLocation());
if (Logger.shouldLog(JFR, DEBUG)) {
Logger.log(JFR, DEBUG, "maxchunksize: " + Options.getMaxChunkSize()+ " bytes");
Logger.log(JFR, DEBUG, "memorysize: " + Options.getMemorySize()+ " bytes");
Logger.log(JFR, DEBUG, "globalbuffersize: " + Options.getGlobalBufferSize()+ " bytes");
Logger.log(JFR, DEBUG, "globalbuffercount: " + Options.getGlobalBufferCount());
Logger.log(JFR, DEBUG, "dumppath: " + Options.getDumpPath());
Logger.log(JFR, DEBUG, "samplethreads: " + Options.getSampleThreads());
Logger.log(JFR, DEBUG, "stackdepth: " + Options.getStackDepth());
Logger.log(JFR, DEBUG, "threadbuffersize: " + Options.getThreadBufferSize());
}
if (Logger.shouldLog(JFR, INFO)) {
Logger.log(JFR, INFO, "Repository base directory: " + Repository.getRepository().getBaseLocation());
}
PlatformRecorder.notifyRecorderInitialized(platformRecorder);
}
}
@@ -149,14 +149,13 @@ public static Method makeWriteMethod(List<FieldInfo> fields) {

public static void logASM(String className, byte[] bytes) {
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.INFO, "Generated bytecode for class " + className);
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE, () -> {
if (Logger.shouldLog(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE)) {
ClassReader cr = new ClassReader(bytes);
ByteArrayOutputStream baos = new ByteArrayOutputStream();
PrintWriter w = new PrintWriter(baos);
w.println("Bytecode:");
cr.accept(new TraceClassVisitor(w), 0);
return baos.toString();
});
};
}

}
@@ -47,12 +47,6 @@ public static void log(LogTag logTag, LogLevel logLevel, String message) {
}
}

public static void log(LogTag logTag, LogLevel logLevel, Supplier<String> messageSupplier) {
if (shouldLog(logTag, logLevel)) {
logInternal(logTag, logLevel, messageSupplier.get());
}
}

private static void logInternal(LogTag logTag, LogLevel logLevel, String message) {
if (message == null || message.length() < MAX_SIZE) {
JVM.log(logTag.id, logLevel.level, message);
@@ -221,7 +221,7 @@ public static List<Type> createTypes() throws IOException {
SAXParser parser = new SAXParserImpl();
MetadataHandler t = new MetadataHandler();
try (InputStream is = new BufferedInputStream(SecuritySupport.getResourceAsStream("/jdk/jfr/internal/types/metadata.xml"))) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, () -> "Parsing metadata.xml");
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Parsing metadata.xml");
try {
parser.parse(is, t);
return t.buildTypes();
@@ -115,7 +115,7 @@ public long start() {
startTime = null;
}
startNanos = recorder.start(this);
Logger.log(LogTag.JFR, LogLevel.INFO, () -> {
if (Logger.shouldLog(LogTag.JFR, LogLevel.INFO)) {
// Only print non-default values so it easy to see
// which options were added
StringJoiner options = new StringJoiner(", ");
@@ -141,8 +141,9 @@ public long start() {
if (optionText.length() != 0) {
optionText = "{" + optionText + "}";
}
return "Started recording \"" + getName() + "\" (" + getId() + ") " + optionText;
});
Logger.log(LogTag.JFR, LogLevel.INFO,
"Started recording \"" + getName() + "\" (" + getId() + ") " + optionText);
};
newState = getState();
}
notifyIfStateChanged(oldState, newState);
@@ -576,12 +577,16 @@ void add(RepositoryChunk c) {
private void added(RepositoryChunk c) {
c.use();
size += c.getSize();
Logger.log(JFR, DEBUG, () -> "Recording \"" + name + "\" (" + id + ") added chunk " + c.toString() + ", current size=" + size);
if (Logger.shouldLog(JFR, DEBUG)) {
Logger.log(JFR, DEBUG, "Recording \"" + name + "\" (" + id + ") added chunk " + c.toString() + ", current size=" + size);
}
}

private void removed(RepositoryChunk c) {
size -= c.getSize();
Logger.log(JFR, DEBUG, () -> "Recording \"" + name + "\" (" + id + ") removed chunk " + c.toString() + ", current size=" + size);
if (Logger.shouldLog(JFR, DEBUG)) {
Logger.log(JFR, DEBUG, "Recording \"" + name + "\" (" + id + ") removed chunk " + c.toString() + ", current size=" + size);
}
c.release();
}

@@ -90,7 +90,9 @@ private void finishWithException(Instant endTime) throws IOException {
unFinishedRAF.close();
this.size = SecuritySupport.getFileSize(chunkFile);
this.endTime = endTime;
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, () -> "Chunk finished: " + chunkFile);
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Chunk finished: " + chunkFile);
}
}

public Instant getStartTime() {
@@ -104,11 +106,15 @@ public Instant getEndTime() {
private void delete(SafePath f) {
try {
SecuritySupport.delete(f);
Logger.log(LogTag.JFR, LogLevel.DEBUG, () -> "Repository chunk " + f + " deleted");
if (Logger.shouldLog(LogTag.JFR, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR, LogLevel.DEBUG, "Repository chunk " + f + " deleted");
}
} catch (IOException e) {
// Probably happens because file is being streamed
// on Windows where files in use can't be removed.
Logger.log(LogTag.JFR, LogLevel.DEBUG, () -> "Repository chunk " + f + " could not be deleted: " + e.getMessage());
if (Logger.shouldLog(LogTag.JFR, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR, LogLevel.DEBUG, "Repository chunk " + f + " could not be deleted: " + e.getMessage());
}
if (f != null) {
FilePurger.add(f);
}
@@ -123,18 +129,24 @@ private void destroy() {
try {
unFinishedRAF.close();
} catch (IOException e) {
Logger.log(LogTag.JFR, LogLevel.ERROR, () -> "Could not close random access file: " + chunkFile.toString() + ". File will not be deleted due to: " + e.getMessage());
if (Logger.shouldLog(LogTag.JFR, LogLevel.ERROR)) {
Logger.log(LogTag.JFR, LogLevel.ERROR, "Could not close random access file: " + chunkFile.toString() + ". File will not be deleted due to: " + e.getMessage());
}
}
}

public synchronized void use() {
++refCount;
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, () -> "Use chunk " + toString() + " ref count now " + refCount);
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Use chunk " + toString() + " ref count now " + refCount);
}
}

public synchronized void release() {
--refCount;
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, () -> "Release chunk " + toString() + " ref count now " + refCount);
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Release chunk " + toString() + " ref count now " + refCount);
}
if (refCount == 0) {
destroy();
}
@@ -68,7 +68,9 @@ private void execute() {
} else {
jvm.emitEvent(type.getId(), JVM.counterTime(), 0);
}
Logger.log(LogTag.JFR_SYSTEM_EVENT, LogLevel.DEBUG, ()-> "Executed periodic hook for " + type.getLogName());
if (Logger.shouldLog(LogTag.JFR_SYSTEM_EVENT, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM_EVENT, LogLevel.DEBUG, "Executed periodic hook for " + type.getLogName());
}
} else {
executeSecure();
}
@@ -84,7 +86,9 @@ private void executeSecure() {
public Void run() {
try {
hook.run();
Logger.log(LogTag.JFR_EVENT, LogLevel.DEBUG, ()-> "Executed periodic hook for " + type.getLogName());
if (Logger.shouldLog(LogTag.JFR_EVENT, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_EVENT, LogLevel.DEBUG, "Executed periodic hook for " + type.getLogName());
}
} catch (Throwable t) {
// Prevent malicious user to propagate exception callback in the wrong context
Logger.log(LogTag.JFR_EVENT, LogLevel.WARN, "Exception occurred during execution of period hook for " + type.getLogName());
@@ -71,7 +71,9 @@ private void dump(PlatformRecording recording) {
recording.stop("Dump on exit");
}
} catch (Exception e) {
Logger.log(LogTag.JFR, LogLevel.DEBUG, () -> "Could not dump recording " + recording.getName() + " on exit.");
if (Logger.shouldLog(LogTag.JFR, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR, LogLevel.DEBUG, "Could not dump recording " + recording.getName() + " on exit.");
}
}
}

@@ -318,9 +318,10 @@ private void fillConstantPools(long abortCP) throws IOException {
final long logLastCP = lastCP;
final long logDelta = delta;
if (logTrace) {
Logger.log(LogTag.JFR_SYSTEM_PARSER, LogLevel.TRACE, () -> {
return "New constant pool: startPosition=" + logLastCP + ", size=" + size + ", deltaToNext=" + logDelta + ", flush=" + flush + ", poolCount=" + poolCount;
});
Logger.log(LogTag.JFR_SYSTEM_PARSER, LogLevel.TRACE,
"New constant pool: startPosition=" + logLastCP +
", size=" + size + ", deltaToNext=" + logDelta +
", flush=" + flush + ", poolCount=" + poolCount);
}
for (int i = 0; i < poolCount; i++) {
long id = input.readLong(); // type id
@@ -158,7 +158,9 @@ public static byte[] retransformCallback(Class<?> klass, byte[] oldBytes) throws
for (int i = 0; i < targetClasses.length; i++) {
if (targetClasses[i].equals(klass)) {
Class<?> c = instrumentationClasses[i];
Logger.log(LogTag.JFR_SYSTEM, LogLevel.TRACE, () -> "Processing instrumentation class: " + c);
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.TRACE)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.TRACE, "Processing instrumentation class: " + c);
}
return new JIClassInstrumentation(instrumentationClasses[i], klass, oldBytes).getNewBytes();
}
}
@@ -75,8 +75,11 @@ public JIMethodCallInliner(int access, String desc, MethodVisitor mv,
this.newClass = newClass;
this.inlineTarget = inlineTarget;

Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG, "MethodCallInliner: targetMethod=" + newClass + "."
if (Logger.shouldLog(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG,
"MethodCallInliner: targetMethod=" + newClass + "."
+ inlineTarget.name + inlineTarget.desc);
}
}

@Override
@@ -96,8 +96,10 @@ public void visitEnd() {
for (MethodNode mn : cn.methods) {
// Check if the method is in the list of methods to copy
if (methodInFilter(mn.name, mn.desc)) {
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG, "Copying method: " + mn.name + mn.desc);
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG, " with mapper: " + typeMap);
if (Logger.shouldLog(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG, "Copying method: " + mn.name + mn.desc);
Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.DEBUG, " with mapper: " + typeMap);
}

String[] exceptions = new String[mn.exceptions.size()];
mn.exceptions.toArray(exceptions);

0 comments on commit 65c461e

Please sign in to comment.