Implement lock contention event logging.
Change-Id: I88b30985590157bb5d04229a97f191b898f141bb
diff --git a/build/Android.common.mk b/build/Android.common.mk
index a0d8392..fd9dba5 100644
--- a/build/Android.common.mk
+++ b/build/Android.common.mk
@@ -180,6 +180,7 @@
LIBART_TARGET_SRC_FILES := \
$(LIBART_COMMON_SRC_FILES) \
src/logging_android.cc \
+ src/monitor_android.cc \
src/runtime_android.cc \
src/thread_android.cc \
src/thread_arm.cc
@@ -187,6 +188,7 @@
LIBART_HOST_SRC_FILES := \
$(LIBART_COMMON_SRC_FILES) \
src/logging_linux.cc \
+ src/monitor_linux.cc \
src/runtime_linux.cc \
src/thread_linux.cc \
src/thread_x86.cc
diff --git a/src/monitor.cc b/src/monitor.cc
index aede4b8..b6f91bc 100644
--- a/src/monitor.cc
+++ b/src/monitor.cc
@@ -93,14 +93,25 @@
#define LW_LOCK_COUNT_SHIFT 19
#define LW_LOCK_COUNT(x) (((x) >> LW_LOCK_COUNT_SHIFT) & LW_LOCK_COUNT_MASK)
+bool (*Monitor::is_sensitive_thread_hook_)() = NULL;
bool Monitor::is_verbose_ = false;
+uint32_t Monitor::lock_profiling_threshold_ = 0;
bool Monitor::IsVerbose() {
return is_verbose_;
}
-void Monitor::SetVerbose(bool is_verbose) {
+bool Monitor::IsSensitiveThread() {
+ if (is_sensitive_thread_hook_ != NULL) {
+ return (*is_sensitive_thread_hook_)();
+ }
+ return false;
+}
+
+void Monitor::Init(bool is_verbose, uint32_t lock_profiling_threshold, bool (*is_sensitive_thread_hook)()) {
is_verbose_ = is_verbose;
+ lock_profiling_threshold_ = lock_profiling_threshold;
+ is_sensitive_thread_hook_ = is_sensitive_thread_hook;
}
Monitor::Monitor(Object* obj)
@@ -182,158 +193,52 @@
return obj_;
}
-/*
-static char *logWriteInt(char *dst, int value) {
- *dst++ = EVENT_TYPE_INT;
- set4LE((uint8_t *)dst, value);
- return dst + 4;
-}
-
-static char *logWriteString(char *dst, const char *value, size_t len) {
- *dst++ = EVENT_TYPE_STRING;
- len = len < 32 ? len : 32;
- set4LE((uint8_t *)dst, len);
- dst += 4;
- memcpy(dst, value, len);
- return dst + len;
-}
-
-#define EVENT_LOG_TAG_dvm_lock_sample 20003
-
-static void logContentionEvent(Thread *self, uint32_t waitMs, uint32_t samplePercent,
- const char *ownerFileName, uint32_t ownerLineNumber)
-{
- const StackSaveArea *saveArea;
- const Method *meth;
- uint32_t relativePc;
- char eventBuffer[174];
- const char *fileName;
- char procName[33];
- char *cp;
- size_t len;
- int fd;
-
- saveArea = SAVEAREA_FROM_FP(self->interpSave.curFrame);
- meth = saveArea->method;
- cp = eventBuffer;
-
- // Emit the event list length, 1 byte.
- *cp++ = 9;
-
- // Emit the process name, <= 37 bytes.
- fd = open("/proc/self/cmdline", O_RDONLY);
- memset(procName, 0, sizeof(procName));
- read(fd, procName, sizeof(procName) - 1);
- close(fd);
- len = strlen(procName);
- cp = logWriteString(cp, procName, len);
-
- // Emit the sensitive thread ("main thread") status, 5 bytes.
- bool isSensitive = false;
- if (gDvm.isSensitiveThreadHook != NULL) {
- isSensitive = gDvm.isSensitiveThreadHook();
- }
- cp = logWriteInt(cp, isSensitive);
-
- // Emit self thread name string, <= 37 bytes.
- std::string selfName = dvmGetThreadName(self);
- cp = logWriteString(cp, selfName.c_str(), selfName.size());
-
- // Emit the wait time, 5 bytes.
- cp = logWriteInt(cp, waitMs);
-
- // Emit the source code file name, <= 37 bytes.
- fileName = dvmGetMethodSourceFile(meth);
- if (fileName == NULL) fileName = "";
- cp = logWriteString(cp, fileName, strlen(fileName));
-
- // Emit the source code line number, 5 bytes.
- relativePc = saveArea->xtra.currentPc - saveArea->method->insns;
- cp = logWriteInt(cp, dvmLineNumFromPC(meth, relativePc));
-
- // Emit the lock owner source code file name, <= 37 bytes.
- if (ownerFileName == NULL) {
- ownerFileName = "";
- } else if (strcmp(fileName, ownerFileName) == 0) {
- // Common case, so save on log space.
- ownerFileName = "-";
- }
- cp = logWriteString(cp, ownerFileName, strlen(ownerFileName));
-
- // Emit the source code line number, 5 bytes.
- cp = logWriteInt(cp, ownerLineNumber);
-
- // Emit the sample percentage, 5 bytes.
- cp = logWriteInt(cp, samplePercent);
-
- assert((size_t)(cp - eventBuffer) <= sizeof(eventBuffer));
- android_btWriteLog(EVENT_LOG_TAG_dvm_lock_sample,
- EVENT_TYPE_LIST,
- eventBuffer,
- (size_t)(cp - eventBuffer));
-}
-*/
-
void Monitor::Lock(Thread* self) {
-// uint32_t waitThreshold, samplePercent;
-// uint64_t waitStart, waitEnd, waitMs;
-
if (owner_ == self) {
lock_count_++;
return;
}
+
+ uint64_t waitStart, waitEnd;
if (!lock_.TryLock()) {
+ uint32_t wait_threshold = lock_profiling_threshold_;
+ const char* current_owner_filename = NULL;
+ uint32_t current_owner_line_number = -1;
{
ScopedThreadStateChange tsc(self, Thread::kBlocked);
-// waitThreshold = gDvm.lockProfThreshold;
-// if (waitThreshold) {
-// waitStart = dvmGetRelativeTimeUsec();
-// }
-// const char* currentOwnerFileName = mon->ownerFileName;
-// uint32_t currentOwnerLineNumber = mon->ownerLineNumber;
+ if (wait_threshold != 0) {
+ waitStart = NanoTime() / 1000;
+ }
+ current_owner_filename = owner_filename_;
+ current_owner_line_number = owner_line_number_;
lock_.Lock();
-// if (waitThreshold) {
-// waitEnd = dvmGetRelativeTimeUsec();
-// }
+ if (wait_threshold != 0) {
+ waitEnd = NanoTime() / 1000;
+ }
}
-// if (waitThreshold) {
-// waitMs = (waitEnd - waitStart) / 1000;
-// if (waitMs >= waitThreshold) {
-// samplePercent = 100;
-// } else {
-// samplePercent = 100 * waitMs / waitThreshold;
-// }
-// if (samplePercent != 0 && ((uint32_t)rand() % 100 < samplePercent)) {
-// logContentionEvent(self, waitMs, samplePercent, currentOwnerFileName, currentOwnerLineNumber);
-// }
-// }
+
+ if (wait_threshold != 0) {
+ uint64_t wait_ms = (waitEnd - waitStart) / 1000;
+ uint32_t sample_percent;
+ if (wait_ms >= wait_threshold) {
+ sample_percent = 100;
+ } else {
+ sample_percent = 100 * wait_ms / wait_threshold;
+ }
+ if (sample_percent != 0 && (static_cast<uint32_t>(rand() % 100) < sample_percent)) {
+ LogContentionEvent(self, wait_ms, sample_percent, current_owner_filename, current_owner_line_number);
+ }
+ }
}
owner_ = self;
DCHECK_EQ(lock_count_, 0);
// When debugging, save the current monitor holder for future
// acquisition failures to use in sampled logging.
-// if (gDvm.lockProfThreshold > 0) {
-// const StackSaveArea *saveArea;
-// const Method *meth;
-// mon->ownerLineNumber = 0;
-// if (self->interpSave.curFrame == NULL) {
-// mon->ownerFileName = "no_frame";
-// } else if ((saveArea = SAVEAREA_FROM_FP(self->interpSave.curFrame)) == NULL) {
-// mon->ownerFileName = "no_save_area";
-// } else if ((meth = saveArea->method) == NULL) {
-// mon->ownerFileName = "no_method";
-// } else {
-// uint32_t relativePc = saveArea->xtra.currentPc - saveArea->method->insns;
-// mon->ownerFileName = (char*) dvmGetMethodSourceFile(meth);
-// if (mon->ownerFileName == NULL) {
-// mon->ownerFileName = "no_method_file";
-// } else {
-// mon->ownerLineNumber = dvmLineNumFromPC(meth, relativePc);
-// }
-// }
-// }
+ if (lock_profiling_threshold_ != 0) {
+ self->GetCurrentLocation(owner_filename_, owner_line_number_);
+ }
}
void ThrowIllegalMonitorStateException(const char* msg) {
diff --git a/src/monitor.h b/src/monitor.h
index 829f0fb..632c5d3 100644
--- a/src/monitor.h
+++ b/src/monitor.h
@@ -63,7 +63,8 @@
~Monitor();
static bool IsVerbose();
- static void SetVerbose(bool is_verbose);
+ static bool IsSensitiveThread();
+ static void Init(bool is_verbose, uint32_t lock_profiling_threshold, bool (*is_sensitive_thread_hook)());
static uint32_t GetThinLockId(uint32_t raw_lock_word);
@@ -86,6 +87,8 @@
static void Inflate(Thread* self, Object* obj);
+ void LogContentionEvent(Thread* self, uint32_t wait_ms, uint32_t sample_percent, const char* owner_filename, uint32_t owner_line_number);
+
void Lock(Thread* self);
bool Unlock(Thread* thread);
@@ -94,7 +97,9 @@
void Wait(Thread* self, int64_t msec, int32_t nsec, bool interruptShouldThrow);
+ static bool (*is_sensitive_thread_hook_)();
static bool is_verbose_;
+ static uint32_t lock_profiling_threshold_;
/* Which thread currently owns the lock? */
Thread* owner_;
diff --git a/src/monitor_android.cc b/src/monitor_android.cc
new file mode 100644
index 0000000..95dd397
--- /dev/null
+++ b/src/monitor_android.cc
@@ -0,0 +1,106 @@
+/*
+ * Copyright (C) 2008 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "monitor.h"
+#include "object.h"
+#include "thread.h"
+
+#include <fcntl.h>
+#include <sys/stat.h>
+#include <sys/types.h>
+
+#include "cutils/log.h"
+
+#define EVENT_LOG_TAG_dvm_lock_sample 20003
+
+namespace art {
+
+static void Set4LE(uint8_t* buf, uint32_t val) {
+ *buf++ = (uint8_t)(val);
+ *buf++ = (uint8_t)(val >> 8);
+ *buf++ = (uint8_t)(val >> 16);
+ *buf = (uint8_t)(val >> 24);
+}
+
+static char* EventLogWriteInt(char* dst, int value) {
+ *dst++ = EVENT_TYPE_INT;
+ Set4LE((uint8_t*) dst, value);
+ return dst + 4;
+}
+
+static char* EventLogWriteString(char* dst, const char* value, size_t len) {
+ *dst++ = EVENT_TYPE_STRING;
+ len = len < 32 ? len : 32;
+ Set4LE((uint8_t*) dst, len);
+ dst += 4;
+ memcpy(dst, value, len);
+ return dst + len;
+}
+
+void Monitor::LogContentionEvent(Thread* self, uint32_t wait_ms, uint32_t sample_percent, const char* owner_filename, uint32_t owner_line_number) {
+ // Emit the event list length, 1 byte.
+ char eventBuffer[174];
+ char* cp = eventBuffer;
+ *cp++ = 9;
+
+ // Emit the process name, <= 37 bytes.
+ int fd = open("/proc/self/cmdline", O_RDONLY);
+ char procName[33];
+ memset(procName, 0, sizeof(procName));
+ read(fd, procName, sizeof(procName) - 1);
+ close(fd);
+ size_t len = strlen(procName);
+ cp = EventLogWriteString(cp, procName, len);
+
+ // Emit the sensitive thread ("main thread") status, 5 bytes.
+ cp = EventLogWriteInt(cp, Monitor::IsSensitiveThread());
+
+ // Emit self thread name string, <= 37 bytes.
+ std::string thread_name(self->GetName()->ToModifiedUtf8());
+ cp = EventLogWriteString(cp, thread_name.c_str(), thread_name.size());
+
+ // Emit the wait time, 5 bytes.
+ cp = EventLogWriteInt(cp, wait_ms);
+
+ // Emit the source code file name, <= 37 bytes.
+ const char* filename;
+ uint32_t line_number;
+ self->GetCurrentLocation(filename, line_number);
+ cp = EventLogWriteString(cp, filename, strlen(filename));
+
+ // Emit the source code line number, 5 bytes.
+ cp = EventLogWriteInt(cp, line_number);
+
+ // Emit the lock owner source code file name, <= 37 bytes.
+ if (owner_filename == NULL) {
+ owner_filename = "";
+ } else if (strcmp(filename, owner_filename) == 0) {
+ // Common case, so save on log space.
+ owner_filename = "-";
+ }
+ cp = EventLogWriteString(cp, owner_filename, strlen(owner_filename));
+
+ // Emit the source code line number, 5 bytes.
+ cp = EventLogWriteInt(cp, owner_line_number);
+
+ // Emit the sample percentage, 5 bytes.
+ cp = EventLogWriteInt(cp, sample_percent);
+
+ CHECK_LE((size_t)(cp - eventBuffer), sizeof(eventBuffer));
+ android_btWriteLog(EVENT_LOG_TAG_dvm_lock_sample, EVENT_TYPE_LIST, eventBuffer, (size_t)(cp - eventBuffer));
+}
+
+} // namespace art
diff --git a/src/monitor_linux.cc b/src/monitor_linux.cc
new file mode 100644
index 0000000..856ebe4
--- /dev/null
+++ b/src/monitor_linux.cc
@@ -0,0 +1,24 @@
+/*
+ * Copyright (C) 2008 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "monitor.h"
+
+namespace art {
+
+void Monitor::LogContentionEvent(Thread*, uint32_t, uint32_t, const char*, uint32_t) {
+}
+
+} // namespace art
diff --git a/src/runtime.cc b/src/runtime.cc
index fd9cc8c..31ba262 100644
--- a/src/runtime.cc
+++ b/src/runtime.cc
@@ -212,6 +212,9 @@
parsed->is_zygote_ = false;
+ parsed->lock_profiling_threshold_ = 0;
+ parsed->hook_is_sensitive_thread_ = NULL;
+
parsed->hook_vfprintf_ = vfprintf;
parsed->hook_exit_ = exit;
parsed->hook_abort_ = abort;
@@ -284,6 +287,10 @@
for (size_t i = 0; i < verbose_options.size(); ++i) {
parsed->verbose_.insert(verbose_options[i]);
}
+ } else if (option.starts_with("-Xlockprofthreshold:")) {
+ parsed->lock_profiling_threshold_ = atoi(option.substr(strlen("-Xlockprofthreshold:")).data());
+ } else if (option == "sensitiveThread") {
+ parsed->hook_is_sensitive_thread_ = reinterpret_cast<bool (*)()>(options[i].second);
} else if (option == "vfprintf") {
parsed->hook_vfprintf_ = reinterpret_cast<int (*)(FILE *, const char*, va_list)>(options[i].second);
} else if (option == "exit") {
@@ -430,7 +437,7 @@
LOG(INFO) << "Runtime::Init -verbose:startup enabled";
}
- Monitor::SetVerbose(options->IsVerbose("monitor"));
+ Monitor::Init(options->IsVerbose("monitor"), options->lock_profiling_threshold_, options->hook_is_sensitive_thread_);
host_prefix_ = options->host_prefix_;
boot_class_path_ = options->boot_class_path_;
diff --git a/src/runtime.h b/src/runtime.h
index 1ca9dca..cbd47b8 100644
--- a/src/runtime.h
+++ b/src/runtime.h
@@ -56,6 +56,8 @@
size_t heap_initial_size_;
size_t heap_maximum_size_;
size_t stack_size_;
+ uint32_t lock_profiling_threshold_;
+ bool (*hook_is_sensitive_thread_)();
jint (*hook_vfprintf_)(FILE* stream, const char* format, va_list ap);
void (*hook_exit_)(jint status);
void (*hook_abort_)();
diff --git a/src/thread.cc b/src/thread.cc
index 95c2995..e72046c 100644
--- a/src/thread.cc
+++ b/src/thread.cc
@@ -364,6 +364,10 @@
return "";
}
+String* Thread::GetName() const {
+ return (peer_ != NULL) ? reinterpret_cast<String*>(gThread_name->GetObject(peer_)) : NULL;
+}
+
void Thread::DumpState(std::ostream& os) const {
std::string thread_name("<native thread without managed peer>");
std::string group_name;
@@ -1142,6 +1146,27 @@
return result;
}
+void Thread::GetCurrentLocation(const char*& source_file, uint32_t& line_number) const {
+ Frame f = top_of_managed_stack_;
+ Method* m = f.GetMethod();
+ // TODO: can this ever happen?
+ if (m->IsCalleeSaveMethod()) {
+ f.Next();
+ m = f.GetMethod();
+ }
+
+ ClassLinker* class_linker = Runtime::Current()->GetClassLinker();
+ Class* c = m->GetDeclaringClass();
+ DexCache* dex_cache = c->GetDexCache();
+ const DexFile& dex_file = class_linker->FindDexFile(dex_cache);
+ const DexFile::ClassDef* class_def = dex_file.FindClassDef(c->GetDescriptor()->ToModifiedUtf8());
+
+ source_file = dex_file.dexGetSourceFile(*class_def);
+
+ uint32_t pc = ManglePc(f.GetReturnPC());
+ line_number = dex_file.GetLineNumFromPC(m, m->ToDexPC(pc));
+}
+
void Thread::ThrowNewExceptionF(const char* exception_class_descriptor, const char* fmt, ...) {
va_list args;
va_start(args, fmt);
diff --git a/src/thread.h b/src/thread.h
index a4e0576..ca8cb03 100644
--- a/src/thread.h
+++ b/src/thread.h
@@ -223,6 +223,12 @@
return tid_;
}
+ // Returns the java.lang.Thread's name, or NULL.
+ String* GetName() const;
+
+ // Returns the current method's declaring class' source file and the current line number.
+ void GetCurrentLocation(const char*& source_file, uint32_t& line_number) const;
+
Object* GetPeer() const {
return peer_;
}