diff options
author | Elliott Hughes <enh@google.com> | 2011-10-17 17:57:47 -0700 |
---|---|---|
committer | Elliott Hughes <enh@google.com> | 2011-10-17 20:21:27 -0700 |
commit | fc86162ce2a3467acb690e18cc8bd9b3daafc606 (patch) | |
tree | 949145ce27225c93a41354460fa76cdc62647076 | |
parent | 24a3c2e9924e8765c4a9b4d383cb8f3b922f9c9f (diff) | |
download | art-fc86162ce2a3467acb690e18cc8bd9b3daafc606.zip art-fc86162ce2a3467acb690e18cc8bd9b3daafc606.tar.gz art-fc86162ce2a3467acb690e18cc8bd9b3daafc606.tar.bz2 |
Implement lock contention event logging.
Change-Id: I88b30985590157bb5d04229a97f191b898f141bb
-rw-r--r-- | build/Android.common.mk | 2 | ||||
-rw-r--r-- | src/monitor.cc | 177 | ||||
-rw-r--r-- | src/monitor.h | 7 | ||||
-rw-r--r-- | src/monitor_android.cc | 106 | ||||
-rw-r--r-- | src/monitor_linux.cc | 24 | ||||
-rw-r--r-- | src/runtime.cc | 9 | ||||
-rw-r--r-- | src/runtime.h | 2 | ||||
-rw-r--r-- | src/thread.cc | 25 | ||||
-rw-r--r-- | src/thread.h | 6 |
9 files changed, 220 insertions, 138 deletions
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_COMMON_SRC_FILES := \ 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_TARGET_SRC_FILES := \ 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 @@ namespace art { #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 @@ Object* Monitor::GetObject() { 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 (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); + } } -// 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); -// } -// } } 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 @@ class Monitor { ~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 @@ class Monitor { 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 @@ class Monitor { 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 @@ Runtime::ParsedOptions* Runtime::ParsedOptions::Create(const Options& options, b 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 @@ Runtime::ParsedOptions* Runtime::ParsedOptions::Create(const Options& options, b 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 @@ bool Runtime::Init(const Options& raw_options, bool ignore_unrecognized) { 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 @@ class Runtime { 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 @@ std::string GetSchedulerGroup(pid_t tid) { 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 @@ jobjectArray Thread::InternalStackTraceToStackTraceElementArray(JNIEnv* env, job 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 @@ class PACKED Thread { 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_; } |