1 /**
2 * Copyright (c) 2021-2022 Huawei Device Co., Ltd.
3 * Licensed under the Apache License, Version 2.0 (the "License");
4 * you may not use this file except in compliance with the License.
5 * You may obtain a copy of the License at
6 *
7 * http://www.apache.org/licenses/LICENSE-2.0
8 *
9 * Unless required by applicable law or agreed to in writing, software
10 * distributed under the License is distributed on an "AS IS" BASIS,
11 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 * See the License for the specific language governing permissions and
13 * limitations under the License.
14 */
15
16 #include "trace.h"
17
18 #include "include/runtime_notification.h"
19 #include "include/runtime.h"
20 #include "include/method.h"
21 #include "include/class.h"
22 #include "plugins.h"
23 #include "runtime/include/runtime.h"
24
25 #include <string>
26
27 namespace panda {
28
29 os::memory::Mutex g_traceLock; // NOLINT(fuchsia-statically-constructed-objects)
30 Trace *volatile Trace::singletonTrace_ = nullptr;
31 bool Trace::isTracing_ = false;
32 // NOLINTNEXTLINE(fuchsia-statically-constructed-objects)
33 LanguageContext Trace::ctx_ = LanguageContext(nullptr);
34
SystemMicroSecond()35 static uint64_t SystemMicroSecond()
36 {
37 timespec current {};
38 clock_gettime(CLOCK_MONOTONIC, ¤t);
39 // NOTE(ht): Deleting OS-specific code, move to libpandabase, issue #3210
40 return static_cast<uint64_t>(current.tv_sec) * UINT64_C(1000000) + // 1000000 - time
41 current.tv_nsec / UINT64_C(1000); // 1000 - time
42 }
43
RealTimeSecond()44 static uint64_t RealTimeSecond()
45 {
46 timespec current {};
47 clock_gettime(CLOCK_REALTIME, ¤t);
48 // NOTE(ht): Deleting OS-specific code, move to libpandabase, issue #3210
49 return static_cast<uint64_t>(current.tv_sec);
50 }
51
ThreadCpuClock(os::thread::NativeHandleType thread,clockid_t * clockId)52 static void ThreadCpuClock(os::thread::NativeHandleType thread, clockid_t *clockId)
53 {
54 pthread_getcpuclockid(thread, clockId);
55 }
GetCpuMicroSecond()56 static uint64_t GetCpuMicroSecond()
57 {
58 auto threadSelf = os::thread::GetNativeHandle();
59 clockid_t clockId;
60 ThreadCpuClock(threadSelf, &clockId);
61 timespec current {};
62 clock_gettime(clockId, ¤t);
63 // NOTE(ht): Deleting OS-specific code, move to libpandabase, issue #3210
64 return static_cast<uint64_t>(current.tv_sec) * UINT64_C(1000000) + // 1000000 - time
65 current.tv_nsec / UINT64_C(1000); // 1000 - time
66 }
67
Trace(PandaUniquePtr<panda::os::unix::file::File> traceFile,size_t bufferSize)68 Trace::Trace(PandaUniquePtr<panda::os::unix::file::File> traceFile, size_t bufferSize)
69 : traceFile_(std::move(traceFile)),
70 bufferSize_(std::max(TRACE_HEADER_REAL_LENGTH, bufferSize)),
71 traceStartTime_(SystemMicroSecond()),
72 baseCpuTime_(GetCpuMicroSecond()),
73 bufferOffset_(0)
74 {
75 buffer_ = MakePandaUnique<uint8_t[]>(bufferSize_); // NOLINT(modernize-avoid-c-arrays)
76 if (memset_s(buffer_.get(), bufferSize_, 0, TRACE_HEADER_LENGTH) != EOK) {
77 LOG(ERROR, RUNTIME) << __func__ << " memset error";
78 }
79 WriteDataByte(buffer_.get(), MAGIC_VALUE, numberOf4Bytes_);
80 WriteDataByte(buffer_.get() + numberOf4Bytes_, TRACE_VERSION, numberOf2Bytes_);
81 WriteDataByte(buffer_.get() + numberOf4Bytes_ + numberOf2Bytes_, TRACE_HEADER_LENGTH, numberOf2Bytes_);
82 WriteDataByte(buffer_.get() + numberOf8Bytes_, traceStartTime_, numberOf8Bytes_);
83 WriteDataByte(buffer_.get() + numberOf8Bytes_ + numberOf8Bytes_, TRACE_ITEM_SIZE, numberOf2Bytes_);
84 // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints
85 // imposed on other reads or writes
86 bufferOffset_.store(TRACE_HEADER_LENGTH, std::memory_order_relaxed);
87 }
88
89 Trace::~Trace() = default;
90
StartTracing(const char * traceFilename,size_t bufferSize)91 void Trace::StartTracing(const char *traceFilename, size_t bufferSize)
92 {
93 os::memory::LockHolder lock(g_traceLock);
94 if (singletonTrace_ != nullptr) {
95 LOG(ERROR, RUNTIME) << "method tracing is running, ignoring new request";
96 return;
97 }
98
99 PandaString fileName(traceFilename);
100 if (fileName.empty()) {
101 fileName = "method";
102 fileName = fileName + ConvertToString(std::to_string(RealTimeSecond()));
103 fileName += ".trace";
104 #ifdef PANDA_TARGET_MOBILE
105 fileName = "/data/misc/trace/" + fileName;
106 #endif // PANDA_TARGET_MOBILE
107 }
108
109 auto traceFile = MakePandaUnique<panda::os::unix::file::File>(
110 panda::os::file::Open(fileName, panda::os::file::Mode::READWRITECREATE).GetFd());
111 if (!traceFile->IsValid()) {
112 LOG(ERROR, RUNTIME) << "Cannot OPEN/CREATE the trace file " << fileName;
113 return;
114 }
115
116 panda_file::SourceLang lang = panda::plugins::RuntimeTypeToLang(Runtime::GetRuntimeType());
117 ctx_ = Runtime::GetCurrent()->GetLanguageContext(lang);
118
119 singletonTrace_ = ctx_.CreateTrace(std::move(traceFile), bufferSize);
120
121 Runtime::GetCurrent()->GetNotificationManager()->AddListener(singletonTrace_,
122 RuntimeNotificationManager::Event::METHOD_EVENTS);
123 isTracing_ = true;
124 }
125
StopTracing()126 void Trace::StopTracing()
127 {
128 os::memory::LockHolder lock(g_traceLock);
129 if (singletonTrace_ == nullptr) {
130 LOG(ERROR, RUNTIME) << "need to stop method tracing, but no method tracing is running";
131 } else {
132 Runtime::GetCurrent()->GetNotificationManager()->RemoveListener(
133 singletonTrace_, RuntimeNotificationManager::Event::METHOD_EVENTS);
134 singletonTrace_->SaveTracingData();
135 isTracing_ = false;
136 Runtime::GetCurrent()->GetInternalAllocator()->Delete(singletonTrace_);
137 singletonTrace_ = nullptr;
138 }
139 }
140
TriggerTracing()141 void Trace::TriggerTracing()
142 {
143 if (!isTracing_) {
144 Trace::StartTracing("", FILE_SIZE);
145 } else {
146 Trace::StopTracing();
147 }
148 }
149
RecordThreadsInfo(PandaOStringStream * os)150 void Trace::RecordThreadsInfo([[maybe_unused]] PandaOStringStream *os)
151 {
152 os::memory::LockHolder lock(threadInfoLock_);
153 for (const auto &info : threadInfoSet_) {
154 (*os) << info;
155 }
156 }
GetAverageTime()157 uint64_t Trace::GetAverageTime()
158 {
159 uint64_t begin = GetCpuMicroSecond();
160 for (int i = 0; i < loopNumber_; i++) {
161 GetCpuMicroSecond();
162 }
163 uint64_t delay = GetCpuMicroSecond() - begin;
164 return delay / divideNumber_;
165 }
166
RecordMethodsInfo(PandaOStringStream * os,const PandaSet<Method * > & calledMethods)167 void Trace::RecordMethodsInfo(PandaOStringStream *os, const PandaSet<Method *> &calledMethods)
168 {
169 for (const auto &method : calledMethods) {
170 (*os) << GetMethodDetailInfo(method);
171 }
172 }
173
WriteInfoToBuf(const ManagedThread * thread,Method * method,EventFlag event,uint32_t threadTime,uint32_t realTime)174 void Trace::WriteInfoToBuf(const ManagedThread *thread, Method *method, EventFlag event, uint32_t threadTime,
175 uint32_t realTime)
176 {
177 // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints
178 // imposed on other reads or writes
179 int32_t writeBeforeOffset = bufferOffset_.load(std::memory_order_relaxed);
180 int32_t writeAfterOffset = 0;
181 do {
182 writeAfterOffset = writeBeforeOffset + TRACE_ITEM_SIZE;
183 if (bufferSize_ < static_cast<size_t>(writeAfterOffset)) {
184 overbrim_ = true;
185 return;
186 }
187 } while (!bufferOffset_.compare_exchange_weak(writeBeforeOffset, writeAfterOffset, std::memory_order_relaxed));
188
189 EventFlag flag = TRACE_METHOD_ENTER;
190 switch (event) {
191 case EventFlag::TRACE_METHOD_ENTER:
192 flag = TRACE_METHOD_ENTER;
193 break;
194 case EventFlag::TRACE_METHOD_EXIT:
195 flag = TRACE_METHOD_EXIT;
196 break;
197 case EventFlag::TRACE_METHOD_UNWIND:
198 flag = TRACE_METHOD_UNWIND;
199 break;
200 default:
201 LOG(ERROR, RUNTIME) << "unrecognized events" << std::endl;
202 }
203 uint32_t methodActionValue = EncodeMethodAndEventToId(method, flag);
204
205 uint8_t *ptr = buffer_.get() + writeBeforeOffset;
206 WriteDataByte(ptr, thread->GetId(), numberOf2Bytes_);
207 // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
208 ptr += numberOf2Bytes_;
209 WriteDataByte(ptr, methodActionValue, numberOf4Bytes_);
210 // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
211 ptr += numberOf4Bytes_;
212 WriteDataByte(ptr, threadTime, numberOf4Bytes_);
213 // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
214 ptr += numberOf4Bytes_;
215 WriteDataByte(ptr, realTime, numberOf4Bytes_);
216 }
217
EncodeMethodAndEventToId(Method * method,EventFlag flag)218 uint32_t Trace::EncodeMethodAndEventToId(Method *method, EventFlag flag)
219 {
220 uint32_t methodActionId = (EncodeMethodToId(method) << ENCODE_EVENT_BITS) | flag;
221 ASSERT(method == DecodeIdToMethod(methodActionId));
222 return methodActionId;
223 }
224
EncodeMethodToId(Method * method)225 uint32_t Trace::EncodeMethodToId(Method *method)
226 {
227 os::memory::LockHolder lock(methodsLock_);
228 uint32_t methodIdValue = 0;
229 auto iter = methodIdPandamap_.find(method);
230 if (iter != methodIdPandamap_.end()) {
231 methodIdValue = iter->second;
232 } else {
233 methodIdValue = methodsCalledVector_.size();
234 methodsCalledVector_.push_back(method);
235 methodIdPandamap_.emplace(method, methodIdValue);
236 }
237 return methodIdValue;
238 }
239
DecodeIdToMethod(uint32_t id)240 Method *Trace::DecodeIdToMethod(uint32_t id)
241 {
242 os::memory::LockHolder lock(methodsLock_);
243 return methodsCalledVector_[id >> ENCODE_EVENT_BITS];
244 }
245
GetUniqueMethods(size_t bufferLength,PandaSet<Method * > * calledMethodsSet)246 void Trace::GetUniqueMethods(size_t bufferLength, PandaSet<Method *> *calledMethodsSet)
247 {
248 uint8_t *dataBegin = buffer_.get() + TRACE_HEADER_LENGTH;
249 uint8_t *dataEnd = buffer_.get() + bufferLength;
250
251 while (dataBegin < dataEnd) {
252 // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
253 uint32_t decodedData = GetDataFromBuffer(dataBegin + numberOf2Bytes_, numberOf4Bytes_);
254 Method *method = DecodeIdToMethod(decodedData);
255 calledMethodsSet->insert(method);
256 // NOLINTNEXTLINE(cppcoreguidelines-pro-bounds-pointer-arithmetic)
257 dataBegin += TRACE_ITEM_SIZE;
258 }
259 }
260
SaveTracingData()261 void Trace::SaveTracingData()
262 {
263 uint64_t elapsed = SystemMicroSecond() - traceStartTime_;
264 PandaOStringStream ostream;
265 ostream << TRACE_STAR_CHAR << "version\n";
266 ostream << TRACE_VERSION << "\n";
267 ostream << "data-file-overflow=" << (overbrim_ ? "true" : "false") << "\n";
268 ostream << "clock=dual\n";
269 ostream << "elapsed-time-usec=" << elapsed << "\n";
270
271 size_t bufEnd;
272 // Atomic with relaxed order reason: data race with buffer_offset_ with no synchronization or ordering constraints
273 // imposed on other reads or writes
274 bufEnd = bufferOffset_.load(std::memory_order_relaxed);
275 size_t numRecords = (bufEnd - TRACE_HEADER_LENGTH) / TRACE_ITEM_SIZE;
276 ostream << "num-method-calls=" << numRecords << "\n";
277 ostream << "clock-call-overhead-nsec=" << GetAverageTime() << "\n";
278 ostream << "pid=" << getpid() << "\n";
279 ostream << "vm=panda\n";
280
281 ostream << TRACE_STAR_CHAR << "threads\n";
282 RecordThreadsInfo(&ostream);
283 ostream << TRACE_STAR_CHAR << "methods\n";
284
285 PandaSet<Method *> calledMethodsSet;
286 GetUniqueMethods(bufEnd, &calledMethodsSet);
287
288 RecordMethodsInfo(&ostream, calledMethodsSet);
289 ostream << TRACE_STAR_CHAR << "end\n";
290 PandaString methodsInfo(ostream.str());
291
292 traceFile_->WriteAll(reinterpret_cast<const void *>(methodsInfo.c_str()), methodsInfo.length());
293 traceFile_->WriteAll(buffer_.get(), bufEnd);
294 traceFile_->Close();
295 }
296
MethodEntry(ManagedThread * thread,Method * method)297 void Trace::MethodEntry(ManagedThread *thread, Method *method)
298 {
299 os::memory::LockHolder lock(threadInfoLock_);
300 uint32_t threadTime = 0;
301 uint32_t realTime = 0;
302 GetTimes(&threadTime, &realTime);
303 WriteInfoToBuf(thread, method, EventFlag::TRACE_METHOD_ENTER, threadTime, realTime);
304
305 PandaOStringStream os;
306 auto threadName = GetThreadName(thread);
307 os << thread->GetId() << "\t" << threadName << "\n";
308 PandaString info = os.str();
309 threadInfoSet_.insert(info);
310 }
311
MethodExit(ManagedThread * thread,Method * method)312 void Trace::MethodExit(ManagedThread *thread, Method *method)
313 {
314 uint32_t threadTime = 0;
315 uint32_t realTime = 0;
316 GetTimes(&threadTime, &realTime);
317 WriteInfoToBuf(thread, method, EventFlag::TRACE_METHOD_EXIT, threadTime, realTime);
318 }
319
GetTimes(uint32_t * threadTime,uint32_t * realTime)320 void Trace::GetTimes(uint32_t *threadTime, uint32_t *realTime)
321 {
322 *threadTime = GetCpuMicroSecond() - baseCpuTime_;
323 *realTime = SystemMicroSecond() - traceStartTime_;
324 }
325
326 } // namespace panda
327