/** * Copyright (c) 2021-2022 Huawei Device Co., Ltd. * 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 "trace.h" #include "include/runtime_notification.h" #include "include/runtime.h" #include "include/method.h" #include "include/class.h" #include "plugins.h" #include "runtime/include/runtime.h" #include namespace panda { Trace *volatile Trace::singleton_trace = nullptr; bool Trace::is_tracing = false; // NOLINTNEXTLINE(fuchsia-statically-constructed-objects) LanguageContext Trace::ctx = LanguageContext(nullptr); static uint64_t SystemMicroSecond() { timespec current {}; clock_gettime(CLOCK_MONOTONIC, ¤t); // TODO(ht): Deleting OS-specific code, move to libpandabase, issue #3210 return static_cast(current.tv_sec) * UINT64_C(1000000) + // 1000000 - time current.tv_nsec / UINT64_C(1000); // 1000 - time } static uint64_t RealTimeSecond() { timespec current {}; clock_gettime(CLOCK_REALTIME, ¤t); // TODO(ht): Deleting OS-specific code, move to libpandabase, issue #3210 return static_cast(current.tv_sec); } static void ThreadCpuClock(os::thread::native_handle_type thread, clockid_t *clock_id) { pthread_getcpuclockid(thread, clock_id); } static uint64_t GetCpuMicroSecond() { auto thread_self = os::thread::GetNativeHandle(); clockid_t clock_id; ThreadCpuClock(thread_self, &clock_id); timespec current {}; clock_gettime(clock_id, ¤t); // TODO(ht): Deleting OS-specific code, move to libpandabase, issue #3210 return static_cast(current.tv_sec) * UINT64_C(1000000) + // 1000000 - time current.tv_nsec / UINT64_C(1000); // 1000 - time } Trace::Trace(PandaUniquePtr trace_file, size_t buffer_size) : trace_file_(std::move(trace_file)), BUFFER_SIZE(std::max(TRACE_HEADER_REAL_LENGTH, buffer_size)), TRACE_START_TIME(SystemMicroSecond()), BASE_CPU_TIME(GetCpuMicroSecond()), buffer_offset_(0), overbrim_(false) { buffer_ = MakePandaUnique(BUFFER_SIZE); // NOLINT(modernize-avoid-c-arrays) if (memset_s(buffer_.get(), BUFFER_SIZE, 0, TRACE_HEADER_LENGTH) != EOK) { LOG(ERROR, RUNTIME) << __func__ << " memset error"; } WriteDataByte(buffer_.get(), MAGIC_VALUE, NUMBER_OF_4BYTES); WriteDataByte(buffer_.get() + NUMBER_OF_4BYTES, TRACE_VERSION, NUMBER_OF_2BYTES); WriteDataByte(buffer_.get() + NUMBER_OF_4BYTES + NUMBER_OF_2BYTES, TRACE_HEADER_LENGTH, NUMBER_OF_2BYTES); WriteDataByte(buffer_.get() + NUMBER_OF_8BYTES, TRACE_START_TIME, NUMBER_OF_8BYTES); WriteDataByte(buffer_.get() + NUMBER_OF_8BYTES + NUMBER_OF_8BYTES, TRACE_ITEM_SIZE, NUMBER_OF_2BYTES); // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints // imposed on other reads or writes buffer_offset_.store(TRACE_HEADER_LENGTH, std::memory_order_relaxed); } Trace::~Trace() = default; void Trace::StartTracing(const char *trace_filename, size_t buffer_size) { os::memory::LockHolder lock(trace_lock); if (singleton_trace != nullptr) { LOG(ERROR, RUNTIME) << "method tracing is running, ignoring new request"; return; } PandaString file_name(trace_filename); if (file_name.empty()) { file_name = "method"; file_name = file_name + ConvertToString(std::to_string(RealTimeSecond())); file_name += ".trace"; #ifdef PANDA_TARGET_MOBILE file_name = "/data/misc/trace/" + file_name; #endif // PANDA_TARGET_MOBILE } auto trace_file = MakePandaUnique( panda::os::file::Open(file_name, panda::os::file::Mode::READWRITECREATE).GetFd()); if (!trace_file->IsValid()) { LOG(ERROR, RUNTIME) << "Cannot OPEN/CREATE the trace file " << file_name; return; } panda_file::SourceLang lang = panda::plugins::RuntimeTypeToLang(Runtime::GetRuntimeType()); ctx = Runtime::GetCurrent()->GetLanguageContext(lang); singleton_trace = ctx.CreateTrace(std::move(trace_file), buffer_size); Runtime::GetCurrent()->GetNotificationManager()->AddListener(singleton_trace, RuntimeNotificationManager::Event::METHOD_EVENTS); is_tracing = true; } void Trace::StopTracing() { os::memory::LockHolder lock(trace_lock); if (singleton_trace == nullptr) { LOG(ERROR, RUNTIME) << "need to stop method tracing, but no method tracing is running"; } else { Runtime::GetCurrent()->GetNotificationManager()->RemoveListener( singleton_trace, RuntimeNotificationManager::Event::METHOD_EVENTS); singleton_trace->SaveTracingData(); is_tracing = false; Runtime::GetCurrent()->GetInternalAllocator()->Delete(singleton_trace); singleton_trace = nullptr; } } void Trace::TriggerTracing() { if (!is_tracing) { Trace::StartTracing("", FILE_SIZE); } else { Trace::StopTracing(); } } void Trace::RecordThreadsInfo([[maybe_unused]] PandaOStringStream *os) { os::memory::LockHolder lock(thread_info_lock_); for (const auto &info : thread_info_set_) { (*os) << info; } } uint64_t Trace::GetAverageTime() { uint64_t begin = GetCpuMicroSecond(); for (int i = 0; i < LOOP_NUMBER; i++) { GetCpuMicroSecond(); } uint64_t delay = GetCpuMicroSecond() - begin; return delay / DIVIDE_NUMBER; } void Trace::RecordMethodsInfo(PandaOStringStream *os, const PandaSet &called_methods) { for (const auto &method : called_methods) { (*os) << GetMethodDetailInfo(method); } } void Trace::WriteInfoToBuf(const ManagedThread *thread, Method *method, EventFlag event, uint32_t thread_time, uint32_t real_time) { int32_t write_after_offset; int32_t write_before_offset; // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints // imposed on other reads or writes write_before_offset = buffer_offset_.load(std::memory_order_relaxed); do { write_after_offset = write_before_offset + TRACE_ITEM_SIZE; if (BUFFER_SIZE < static_cast(write_after_offset)) { overbrim_ = true; return; } } while (!buffer_offset_.compare_exchange_weak(write_before_offset, write_after_offset, std::memory_order_relaxed)); EventFlag flag = TRACE_METHOD_ENTER; switch (event) { case EventFlag::TRACE_METHOD_ENTER: flag = TRACE_METHOD_ENTER; break; case EventFlag::TRACE_METHOD_EXIT: flag = TRACE_METHOD_EXIT; break; case EventFlag::TRACE_METHOD_UNWIND: flag = TRACE_METHOD_UNWIND; break; default: LOG(ERROR, RUNTIME) << "unrecognized events" << std::endl; } uint32_t method_action_value = EncodeMethodAndEventToId(method, flag); uint8_t *ptr = buffer_.get() + write_before_offset; WriteDataByte(ptr, thread->GetId(), NUMBER_OF_2BYTES); // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) ptr += NUMBER_OF_2BYTES; WriteDataByte(ptr, method_action_value, NUMBER_OF_4BYTES); // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) ptr += NUMBER_OF_4BYTES; WriteDataByte(ptr, thread_time, NUMBER_OF_4BYTES); // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) ptr += NUMBER_OF_4BYTES; WriteDataByte(ptr, real_time, NUMBER_OF_4BYTES); } uint32_t Trace::EncodeMethodAndEventToId(Method *method, EventFlag flag) { uint32_t method_action_id = (EncodeMethodToId(method) << ENCODE_EVENT_BITS) | flag; ASSERT(method == DecodeIdToMethod(method_action_id)); return method_action_id; } uint32_t Trace::EncodeMethodToId(Method *method) { os::memory::LockHolder lock(methods_lock_); uint32_t method_id_value; auto iter = method_id_pandamap_.find(method); if (iter != method_id_pandamap_.end()) { method_id_value = iter->second; } else { method_id_value = methods_called_vector_.size(); methods_called_vector_.push_back(method); method_id_pandamap_.emplace(method, method_id_value); } return method_id_value; } Method *Trace::DecodeIdToMethod(uint32_t id) { os::memory::LockHolder lock(methods_lock_); return methods_called_vector_[id >> ENCODE_EVENT_BITS]; } void Trace::GetUniqueMethods(size_t buffer_length, PandaSet *called_methods_set) { uint8_t *data_begin = buffer_.get() + TRACE_HEADER_LENGTH; uint8_t *data_end = buffer_.get() + buffer_length; while (data_begin < data_end) { // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) uint32_t decoded_data = GetDataFromBuffer(data_begin + NUMBER_OF_2BYTES, NUMBER_OF_4BYTES); Method *method = DecodeIdToMethod(decoded_data); called_methods_set->insert(method); // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic) data_begin += TRACE_ITEM_SIZE; } } void Trace::SaveTracingData() { uint64_t elapsed = SystemMicroSecond() - TRACE_START_TIME; PandaOStringStream ostream; ostream << TRACE_STAR_CHAR << "version\n"; ostream << TRACE_VERSION << "\n"; ostream << "data-file-overflow=" << (overbrim_ ? "true" : "false") << "\n"; ostream << "clock=dual\n"; ostream << "elapsed-time-usec=" << elapsed << "\n"; size_t buf_end; // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints // imposed on other reads or writes buf_end = buffer_offset_.load(std::memory_order_relaxed); size_t num_records = (buf_end - TRACE_HEADER_LENGTH) / TRACE_ITEM_SIZE; ostream << "num-method-calls=" << num_records << "\n"; ostream << "clock-call-overhead-nsec=" << GetAverageTime() << "\n"; ostream << "pid=" << getpid() << "\n"; ostream << "vm=panda\n"; ostream << TRACE_STAR_CHAR << "threads\n"; RecordThreadsInfo(&ostream); ostream << TRACE_STAR_CHAR << "methods\n"; PandaSet called_methods_set; GetUniqueMethods(buf_end, &called_methods_set); RecordMethodsInfo(&ostream, called_methods_set); ostream << TRACE_STAR_CHAR << "end\n"; PandaString methods_info(ostream.str()); trace_file_->WriteAll(reinterpret_cast(methods_info.c_str()), methods_info.length()); trace_file_->WriteAll(buffer_.get(), buf_end); trace_file_->Close(); } void Trace::MethodEntry(ManagedThread *thread, Method *method) { os::memory::LockHolder lock(thread_info_lock_); uint32_t thread_time = 0; uint32_t real_time = 0; GetTimes(&thread_time, &real_time); WriteInfoToBuf(thread, method, EventFlag::TRACE_METHOD_ENTER, thread_time, real_time); PandaOStringStream os; auto thread_name = GetThreadName(thread); os << thread->GetId() << "\t" << thread_name << "\n"; PandaString info = os.str(); thread_info_set_.insert(info); } void Trace::MethodExit(ManagedThread *thread, Method *method) { uint32_t thread_time = 0; uint32_t real_time = 0; GetTimes(&thread_time, &real_time); WriteInfoToBuf(thread, method, EventFlag::TRACE_METHOD_EXIT, thread_time, real_time); } void Trace::GetTimes(uint32_t *thread_time, uint32_t *real_time) { *thread_time = GetCpuMicroSecond() - BASE_CPU_TIME; *real_time = SystemMicroSecond() - TRACE_START_TIME; } } // namespace panda