Skip to content
Permalink
Browse files
8264768: JFR: Allow events to be printed to the log
Reviewed-by: mgronlun
  • Loading branch information
egahlin committed Apr 13, 2021
1 parent 3b576ed commit e80012ede3564a868abc1705f332bcee942baf48
Showing 29 changed files with 1,114 additions and 31 deletions.
@@ -488,25 +488,27 @@ Klass* JfrJavaSupport::klass(const jobject handle) {
}

// caller needs ResourceMark
const char* JfrJavaSupport::c_str(jstring string, Thread* t) {
const char* JfrJavaSupport::c_str(oop string, Thread* t) {
DEBUG_ONLY(check_java_thread_in_vm(t));
if (string == NULL) {
return NULL;
}
const char* temp = NULL;
const oop java_string = resolve_non_null(string);
const typeArrayOop value = java_lang_String::value(java_string);
char* resource_copy = NULL;
const typeArrayOop value = java_lang_String::value(string);
if (value != NULL) {
const size_t length = java_lang_String::utf8_length(java_string, value);
temp = NEW_RESOURCE_ARRAY_IN_THREAD(t, const char, (length + 1));
if (temp == NULL) {
JfrJavaSupport::throw_out_of_memory_error("Unable to allocate thread local native memory", t);
return NULL;
const int length = java_lang_String::utf8_length(string, value);
resource_copy = NEW_RESOURCE_ARRAY_IN_THREAD(t, char, (length + 1));
if (resource_copy == NULL) {
JfrJavaSupport::throw_out_of_memory_error("Unable to allocate thread local native memory", t);
return NULL;
}
assert(temp != NULL, "invariant");
java_lang_String::as_utf8_string(java_string, value, const_cast<char*>(temp), (int) length + 1);
assert(resource_copy != NULL, "invariant");
java_lang_String::as_utf8_string(string, value, resource_copy, length + 1);
}
return temp;
return resource_copy;
}

// caller needs ResourceMark
const char* JfrJavaSupport::c_str(jstring string, Thread* t) {
DEBUG_ONLY(check_java_thread_in_vm(t));
return string != NULL ? c_str(resolve_non_null(string), t) : NULL;
}

/*
@@ -77,6 +77,7 @@ class JfrJavaSupport : public AllStatic {
static Klass* klass(const jobject handle);
// caller needs ResourceMark
static const char* c_str(jstring string, Thread* jt);
static const char* c_str(oop string, Thread* t);

// exceptions
static void throw_illegal_state_exception(const char* message, TRAPS);
@@ -258,6 +258,10 @@ JVM_ENTRY_NO_ENV(void, jfr_log(JNIEnv* env, jobject jvm, jint tag_set, jint leve
JfrJavaLog::log(tag_set, level, message, thread);
JVM_END

JVM_ENTRY_NO_ENV(void, jfr_log_event(JNIEnv* env, jobject jvm, jint level, jobjectArray lines, jboolean system))
JfrJavaLog::log_event(env, level, lines, system == JNI_TRUE, thread);
JVM_END

JVM_ENTRY_NO_ENV(void, jfr_subscribe_log_level(JNIEnv* env, jobject jvm, jobject log_tag, jint id))
JfrJavaLog::subscribe_log_level(log_tag, id, thread);
JVM_END
@@ -71,6 +71,8 @@ void JNICALL jfr_subscribe_log_level(JNIEnv* env, jobject jvm, jobject log_tag,

void JNICALL jfr_log(JNIEnv* env, jobject jvm, jint tag_set, jint level, jstring message);

void JNICALL jfr_log_event(JNIEnv* env, jobject jvm, jint level, jobjectArray lines, jboolean system);

void JNICALL jfr_retransform_classes(JNIEnv* env, jobject jvm, jobjectArray classes);

void JNICALL jfr_set_enabled(JNIEnv* env, jobject jvm, jlong event_type_id, jboolean enabled);
@@ -51,6 +51,7 @@ JfrJniMethodRegistration::JfrJniMethodRegistration(JNIEnv* env) {
(char*)"getTicksFrequency", (char*)"()J", (void*)jfr_elapsed_frequency,
(char*)"subscribeLogLevel", (char*)"(Ljdk/jfr/internal/LogTag;I)V", (void*)jfr_subscribe_log_level,
(char*)"log", (char*)"(IILjava/lang/String;)V", (void*)jfr_log,
(char*)"logEvent", (char*)"(I[Ljava/lang/String;Z)V", (void*)jfr_log_event,
(char*)"retransformClasses", (char*)"([Ljava/lang/Class;)V", (void*)jfr_retransform_classes,
(char*)"setEnabled", (char*)"(JZ)V", (void*)jfr_set_enabled,
(char*)"setFileNotification", (char*)"(J)V", (void*)jfr_set_file_notification,
@@ -156,7 +156,6 @@ void JfrNetworkUtilization::send_events() {
if (!get_interfaces(&network_interfaces)) {
return;
}
log_trace(jfr, event)("Reporting network utilization");
static JfrTicks last_sample_instant;
const JfrTicks cur_time = JfrTicks::now();
if (cur_time > last_sample_instant) {
@@ -28,7 +28,9 @@
#include "jfr/utilities/jfrLogTagSets.hpp"
#include "logging/log.hpp"
#include "logging/logConfiguration.hpp"
#include "logging/logMessage.hpp"
#include "memory/resourceArea.hpp"
#include "oops/objArrayOop.inline.hpp"
#include "runtime/thread.inline.hpp"

#define JFR_LOG_TAGS_CONCATED(T0, T1, T2, T3, T4, T5, ...) \
@@ -119,6 +121,38 @@ void JfrJavaLog::subscribe_log_level(jobject log_tag, jint id, TRAPS) {
}
}

void JfrJavaLog::log_event(JNIEnv* env, jint level, jobjectArray lines, bool system, TRAPS) {
DEBUG_ONLY(JfrJavaSupport::check_java_thread_in_vm(THREAD));
if (lines == NULL) {
return;
}
if (level < (jint)LogLevel::First || level > (jint)LogLevel::Last) {
JfrJavaSupport::throw_illegal_argument_exception("LogLevel passed is outside valid range", THREAD);
return;
}

objArrayOop the_lines = objArrayOop(JfrJavaSupport::resolve_non_null(lines));
assert(the_lines != NULL, "invariant");
assert(the_lines->is_array(), "must be array");
const int length = the_lines->length();

ResourceMark rm(THREAD);
LogMessage(jfr, event) jfr_event;
LogMessage(jfr, system, event) jfr_event_system;
for (int i = 0; i < length; ++i) {
const char* text = JfrJavaSupport::c_str(the_lines->obj_at(i), THREAD);
if (text == NULL) {
// An oome has been thrown and is pending.
return;
}
if (system) {
jfr_event_system.write((LogLevelType)level, "%s", text);
} else {
jfr_event.write((LogLevelType)level, "%s", text);
}
}
}

void JfrJavaLog::log(jint tag_set, jint level, jstring message, TRAPS) {
DEBUG_ONLY(JfrJavaSupport::check_java_thread_in_vm(THREAD));
if (message == NULL) {
@@ -43,6 +43,7 @@ class JfrJavaLog : public AllStatic {
public:
static void subscribe_log_level(jobject log_tag, jint id, TRAPS);
static void log(jint tag_set, jint level, jstring message, TRAPS);
static void log_event(JNIEnv* env, jint level, jobjectArray lines, bool system, TRAPS);
};

#endif // SHARE_JFR_UTILITIES_JFRJAVALOG_HPP
@@ -188,6 +188,17 @@ private JVM() {
*/
public static native void log(int tagSetId, int level, String message);

/**
* Log an event to jfr+event or jfr+event+system.
* <p>
* Caller should ensure that message is not null or too large to handle.
*
* @param level log level
* @param lines lines to log
* @param system if lines should be written to jfr+event+system
*/
public static native void logEvent(int level, String[] lines, boolean system);

/**
* Subscribe to LogLevel updates for LogTag
*
@@ -95,4 +95,13 @@ public enum LogTag {
LogTag(int tagId) {
id = tagId;
}
}

public LogLevel level() {
for (LogLevel l : LogLevel.values()) {
if (l.level == tagSetLevel) {
return l;
}
}
return LogLevel.WARN; // default
}
}
@@ -25,14 +25,17 @@

package jdk.jfr.internal;

import java.util.Arrays;

/**
* JFR logger
*
*/

public final class Logger {

private static final int MAX_SIZE = 10000;
private static final int MAX_SIZE = 10_000;
private static final int MAX_EVENT_SIZE = 100_000;
static {
// This will try to initialize the JVM logging system
JVMSupport.tryToInitializeJVM();
@@ -45,6 +48,25 @@ public static void log(LogTag logTag, LogLevel logLevel, String message) {
}
}

public static void logEvent(LogLevel logLevel, String[] lines, boolean system) {
if (lines == null || lines.length == 0) {
return;
}
if (shouldLog(LogTag.JFR_EVENT, logLevel) || shouldLog(LogTag.JFR_SYSTEM_EVENT, logLevel)) {
int size = 0;
for (int i = 0; i < lines.length; i++) {
String line = lines[i];
if (size + line.length() > MAX_EVENT_SIZE) {
lines = Arrays.copyOf(lines, i + 1);
lines[i] = "...";
break;
}
size+=line.length();
}
JVM.logEvent(logLevel.level, lines, system);
}
}

private static void logInternal(LogTag logTag, LogLevel logLevel, String message) {
if (message == null || message.length() < MAX_SIZE) {
JVM.log(logTag.id, logLevel.level, message);
@@ -39,7 +39,7 @@
*/
public final class PlatformEventType extends Type {
private final boolean isJVM;
private final boolean isJDK;
private final boolean isJDK;
private final boolean isMethodSampling;
private final List<SettingDescriptor> settings = new ArrayList<>(5);
private final boolean dynamicSettings;
@@ -188,6 +188,10 @@ public boolean isEnabled() {
return enabled;
}

public boolean isSystem() {
return isJVM || isJDK;
}

public boolean isJVM() {
return isJVM;
}
@@ -285,7 +289,7 @@ public boolean setRegistered(boolean registered) {
if (this.registered != registered) {
this.registered = registered;
updateCommittable();
LogTag logTag = isJVM() || isJDK() ? LogTag.JFR_SYSTEM_EVENT : LogTag.JFR_EVENT;
LogTag logTag = isSystem() ? LogTag.JFR_SYSTEM_METADATA : LogTag.JFR_METADATA;
if (registered) {
Logger.log(logTag, LogLevel.INFO, "Registered " + getLogName());
} else {
@@ -57,12 +57,13 @@
import jdk.jfr.events.ActiveSettingEvent;
import jdk.jfr.internal.SecuritySupport.SafePath;
import jdk.jfr.internal.SecuritySupport.SecureRecorderListener;
import jdk.jfr.internal.consumer.EventLog;
import jdk.jfr.internal.instrument.JDKEvents;

public final class PlatformRecorder {


private final List<PlatformRecording> recordings = new ArrayList<>();
private final ArrayList<PlatformRecording> recordings = new ArrayList<>();
private static final List<SecureRecorderListener> changeListeners = new ArrayList<>();
private final Repository repository;
private static final JVM jvm = JVM.getJVM();
@@ -245,6 +246,9 @@ synchronized long start(PlatformRecording recording) {
RepositoryChunk newChunk = null;
if (toDisk) {
newChunk = repository.newChunk(zdtNow);
if (EventLog.shouldLog()) {
EventLog.start();
}
MetadataRepository.getInstance().setOutput(newChunk.getFile().toString());
} else {
MetadataRepository.getInstance().setOutput(null);
@@ -259,6 +263,9 @@ synchronized long start(PlatformRecording recording) {
RepositoryChunk newChunk = null;
if (toDisk) {
newChunk = repository.newChunk(zdtNow);
if (EventLog.shouldLog()) {
EventLog.start();
}
RequestEngine.doChunkEnd();
MetadataRepository.getInstance().setOutput(newChunk.getFile().toString());
startNanos = jvm.getChunkStartNanos();
@@ -347,6 +354,9 @@ synchronized void stop(PlatformRecording recording) {
RequestEngine.setFlushInterval(Long.MAX_VALUE);
}
recording.setState(RecordingState.STOPPED);
if (!isToDisk()) {
EventLog.stop();
}
}

private void dumpMemoryToDestination(PlatformRecording recording) {
@@ -476,13 +486,28 @@ private void periodicTask() {
if (jvm.shouldRotateDisk()) {
rotateDisk();
}
if (isToDisk()) {
EventLog.update();
}
}
long minDelta = RequestEngine.doPeriodic();
long wait = Math.min(minDelta, Options.getWaitInterval());
takeNap(wait);
}
}

private boolean isToDisk() {
// Use indexing to avoid Iterator allocation if nothing happens
int count = recordings.size();
for (int i = 0; i < count; i++) {
PlatformRecording r = recordings.get(i);
if (r.isToDisk() && r.getState() == RecordingState.RUNNING) {
return true;
}
}
return false;
}

private void takeNap(long duration) {
try {
synchronized (JVM.FILE_DELTA_CHANGE) {
@@ -68,15 +68,15 @@ private void execute() {
} else {
jvm.emitEvent(type.getId(), JVM.counterTime(), 0);
}
if (Logger.shouldLog(LogTag.JFR_SYSTEM_EVENT, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM_EVENT, LogLevel.DEBUG, "Executed periodic hook for " + type.getLogName());
if (Logger.shouldLog(LogTag.JFR_SYSTEM, LogLevel.DEBUG)) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.DEBUG, "Executed periodic hook for " + type.getLogName());
}
} else {
executeSecure();
}
} catch (Throwable e) {
// Prevent malicious user to propagate exception callback in the wrong context
Logger.log(LogTag.JFR_SYSTEM_EVENT, LogLevel.WARN, "Exception occurred during execution of period hook for " + type.getLogName());
Logger.log(LogTag.JFR_SYSTEM, LogLevel.WARN, "Exception occurred during execution of period hook for " + type.getLogName());
}
}

@@ -137,10 +137,10 @@ public static void addTrustedJDKHook(Class<? extends Event> eventClass, Runnable
}

private static void logHook(String action, PlatformEventType type) {
if (type.isJDK() || type.isJVM()) {
Logger.log(LogTag.JFR_SYSTEM_EVENT, LogLevel.INFO, action + " periodic hook for " + type.getLogName());
if (type.isSystem()) {
Logger.log(LogTag.JFR_SYSTEM, LogLevel.INFO, action + " periodic hook for " + type.getLogName());
} else {
Logger.log(LogTag.JFR_EVENT, LogLevel.INFO, action + " periodic hook for " + type.getLogName());
Logger.log(LogTag.JFR, LogLevel.INFO, action + " periodic hook for " + type.getLogName());
}
}

@@ -469,7 +469,7 @@ public static Thread createThreadWitNoPermissions(String threadName, Runnable ru
return doPrivilegedWithReturn(() -> new Thread(runnable, threadName), new Permission[0]);
}

static void setDaemonThread(Thread t, boolean daemon) {
public static void setDaemonThread(Thread t, boolean daemon) {
doPrivileged(()-> t.setDaemon(daemon), new RuntimePermission("modifyThread"));
}

@@ -66,6 +66,8 @@ public abstract class AbstractEventStream implements EventStream {

private volatile boolean closed;

private boolean daemon = false;

AbstractEventStream(AccessControlContext acc, PlatformRecording recording, List<Configuration> configurations) throws IOException {
this.accessControllerContext = Objects.requireNonNull(acc);
this.recording = recording;
@@ -101,6 +103,11 @@ public final void setReuse(boolean reuse) {
streamConfiguration.setReuse(reuse);
}

// Only used if -Xlog:jfr+event* is specified
public final void setDaemon(boolean daemon) {
this.daemon = daemon;
}

@Override
public final void setStartTime(Instant startTime) {
Objects.nonNull(startTime);
@@ -219,6 +226,7 @@ public final void startAsync(long startNanos) {
startInternal(startNanos);
Runnable r = () -> run(accessControllerContext);
thread = SecuritySupport.createThreadWitNoPermissions(nextThreadName(), r);
SecuritySupport.setDaemonThread(thread, daemon);
thread.start();
}

1 comment on commit e80012e

@openjdk-notifier
Copy link

@openjdk-notifier openjdk-notifier bot commented on e80012e Apr 13, 2021

Choose a reason for hiding this comment

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

Please sign in to comment.