1 /*
2 * Copyright (c) 2024 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 "ecmascript/module/module_logger.h"
17
18 #include "ecmascript/ecma_context.h"
19 #include "ecmascript/module/module_path_helper.h"
20 #include "ecmascript/platform/parameters.h"
21 #include "ecmascript/runtime_lock.h"
22 namespace panda::ecmascript {
23
ModuleLogger(EcmaVM * vm)24 ModuleLogger::ModuleLogger(EcmaVM *vm) : vm_(vm)
25 {
26 tid_ = os::thread::GetCurrentThreadId();
27 }
28
PrintModuleLoadInfo()29 void ModuleLogger::PrintModuleLoadInfo()
30 {
31 ProcessModuleExecuteTime();
32 // copy jsModuleLoadInfo from map to vector in order to sort by cost time.
33 jsModuleLoadInfoRes_.insert(jsModuleLoadInfoRes_.begin(), jsModuleLoadInfo_.begin(), jsModuleLoadInfo_.end());
34 std::sort(jsModuleLoadInfoRes_.begin(), jsModuleLoadInfoRes_.end(),
35 [](auto &x, auto &y) { return x.second->time > y.second->time; });
36 PrintSummary();
37 PrintUsedFileInfo();
38 PrintUnusedFileInfo();
39 }
40
CreateResultFile(std::string & path) const41 bool ModuleLogger::CreateResultFile(std::string &path) const
42 {
43 path = base::ConcatToCString(FILEDIR, vm_->GetBundleName());
44 if (vm_->IsWorkerThread()) {
45 base::AppendToBaseString(path, "_", std::to_string(tid_));
46 }
47 path += SUFFIX;
48 constexpr mode_t defaultMode = S_IRUSR | S_IWUSR | S_IRGRP; // -rw-r--
49 int fd = creat(path.c_str(), defaultMode);
50 if (fd == -1) {
51 LOG_ECMA(ERROR) << "file create failed, errno = "<< errno;
52 return false;
53 }
54 close(fd);
55 return true;
56 }
57
OpenResultFile(std::string & path) const58 bool ModuleLogger::OpenResultFile(std::string &path) const
59 {
60 path = base::ConcatToCString(FILEDIR, vm_->GetBundleName());
61 if (vm_->IsWorkerThread()) {
62 base::AppendToBaseString(path, "_", std::to_string(tid_));
63 }
64 path += SUFFIX;
65 if (access(path.c_str(), F_OK) == 0) {
66 if (access(path.c_str(), W_OK) == 0) {
67 LOG_ECMA(DEBUG) << "file open success";
68 return true;
69 }
70 LOG_ECMA(ERROR) << "file create failed, W_OK false";
71 return false;
72 }
73 return CreateResultFile(path);
74 }
75
InsertModuleLoadInfo(JSHandle<SourceTextModule> currentModule,JSHandle<SourceTextModule> exportModule,int32_t index)76 void ModuleLogger::InsertModuleLoadInfo(JSHandle<SourceTextModule> currentModule,
77 JSHandle<SourceTextModule> exportModule, int32_t index)
78 {
79 JSThread *thread = vm_->GetJSThread();
80 RuntimeLockHolder locker(thread, mutex_);
81 CString curName = SourceTextModule::GetModuleName(currentModule.GetTaggedValue());
82 CString sonName = SourceTextModule::GetModuleName(exportModule.GetTaggedValue());
83 ModuleLoadInfo *sonModule = GetModuleLoadInfo(sonName);
84 sonModule->isUsed = true;
85 // get importName
86 CString exportNameStr;
87 if (index < 0) {
88 exportNameStr = "*";
89 } else {
90 JSHandle<TaggedArray> importArray(thread, currentModule->GetImportEntries());
91 JSHandle<ImportEntry> importEntry(thread, importArray->Get(index));
92 JSHandle<JSTaggedValue> importName(thread, importEntry->GetImportName());
93 exportNameStr = ModulePathHelper::Utf8ConvertToString(importName.GetTaggedValue());
94 }
95 auto &upLevelInfo = sonModule->upLevel;
96 auto ulModule = upLevelInfo.find(curName);
97 if (ulModule == upLevelInfo.end()) {
98 CSet<CString> tmp;
99 tmp.insert(exportNameStr);
100 upLevelInfo.emplace(curName, std::move(tmp));
101 return;
102 }
103 ulModule->second.insert(exportNameStr);
104 }
105
InsertParentModule(JSHandle<SourceTextModule> currentModule,JSHandle<SourceTextModule> requiredModule)106 void ModuleLogger::InsertParentModule(JSHandle<SourceTextModule> currentModule,
107 JSHandle<SourceTextModule> requiredModule)
108 {
109 RuntimeLockHolder locker(vm_->GetJSThread(), mutex_);
110 CString curName = currentModule->GetEcmaModuleRecordNameString();
111 CString sonName = requiredModule->GetEcmaModuleRecordNameString();
112 ModuleLoadInfo *sonModule = GetModuleLoadInfo(sonName);
113 sonModule->parentModules.insert(std::move(curName));
114 }
115
InsertEntryPointModule(JSHandle<SourceTextModule> currentModule)116 void ModuleLogger::InsertEntryPointModule(JSHandle<SourceTextModule> currentModule)
117 {
118 RuntimeLockHolder locker(vm_->GetJSThread(), mutex_);
119 CString curName = currentModule->GetEcmaModuleRecordNameString();
120 ModuleLoadInfo *curModule = GetModuleLoadInfo(curName);
121 curModule->isUsed = true;
122 auto &upLevelInfo = curModule->upLevel;
123 CSet<CString> tmp;
124 upLevelInfo.emplace("EntryPoint", tmp);
125 }
126
PrintSummary() const127 void ModuleLogger::PrintSummary() const
128 {
129 std::string path;
130 if (!CreateResultFile(path)) {
131 LOG_ECMA(ERROR) << "open file fail, no log anymore";
132 return;
133 }
134 std::ofstream fileHandle;
135 fileHandle.open(path, std::ios_base::app);
136 std::string start = base::ConcatToStdString("<----Summary----> Total file number: ",
137 std::to_string(totalFileNumber_), ", total time: ",
138 std::to_string(totalTime_), "ms, including used file:", std::to_string(usedFileNumber_),
139 ", cost time: ", std::to_string(usedFileTime_), "ms, and unused file: ",
140 std::to_string(unusedFileNumber_), ", cost time: ", std::to_string(unusedFileTime_), "ms\n");
141 fileHandle << start;
142 fileHandle.close();
143 }
144
PrintUsedFileInfo() const145 void ModuleLogger::PrintUsedFileInfo() const
146 {
147 std::string path;
148 if (!OpenResultFile(path)) {
149 LOG_ECMA(ERROR) << "open file fail, no log anymore";
150 return;
151 }
152 std::ofstream fileHandle;
153 fileHandle.open(path, std::ios_base::app);
154 std::string start = base::ConcatToStdString("<----used file start----> used file: ",
155 std::to_string(usedFileNumber_), ", cost time: ", std::to_string(usedFileTime_), "ms\n");
156 fileHandle << start;
157 int32_t fileNumber = 1;
158 for (auto &i : jsModuleLoadInfoRes_) {
159 ModuleLoadInfo *info = i.second;
160 if (info->isUsed) {
161 std::string content = base::ConcatToStdString("used file ",
162 std::to_string(fileNumber++), ": ", i.first.c_str(),
163 ", cost time: ", ToStringWithPrecision(info->time, THREE), "ms\n");
164 fileHandle << content;
165 auto &upInfo = info->upLevel;
166 int32_t parentModuleCount = 1;
167 for (auto &k : upInfo) {
168 std::string parentInfoStr = base::ConcatToStdString(" parentModule ",
169 std::to_string(parentModuleCount++), ": ", k.first.c_str(), " ");
170 for (auto &exportN : k.second) {
171 base::AppendToBaseString(parentInfoStr, exportN, " ");
172 }
173 parentInfoStr += "\n";
174 fileHandle << parentInfoStr;
175 }
176 }
177 }
178 std::string end = "<----------used file end----------> \n";
179 fileHandle << end;
180 fileHandle.close();
181 }
182
PrintUnusedFileInfo() const183 void ModuleLogger::PrintUnusedFileInfo() const
184 {
185 std::string path;
186 if (!OpenResultFile(path)) {
187 LOG_ECMA(ERROR) << "open file fail, no log anymore";
188 return;
189 }
190 std::ofstream fileHandle;
191 fileHandle.open(path, std::ios_base::app);
192 std::string start = base::ConcatToStdString("<----unused file start----> unused file: ",
193 std::to_string(unusedFileNumber_), ", cost time: ", std::to_string(unusedFileTime_), "ms\n");
194 fileHandle << start;
195 int32_t fileNumber = 1;
196 for (auto &i : jsModuleLoadInfoRes_) {
197 ModuleLoadInfo *info = i.second;
198 if (!info->isUsed) {
199 std::string content = base::ConcatToStdString("unused file ", std::to_string(fileNumber++), ": ",
200 i.first.c_str(), ", cost time: ", ToStringWithPrecision(info->time, THREE), "ms\n");
201 fileHandle << content;
202 int32_t parentNumber = 1;
203 CSet<CString> parents = info->parentModules;
204 for (auto &k : parents) {
205 std::string parent = base::ConcatToStdString(" parentModule ",
206 std::to_string(parentNumber++), ": ", k.c_str(), "\n");
207 fileHandle << parent;
208 }
209 }
210 }
211 std::string end = "<----------unused file end----------> \n";
212 fileHandle << end;
213 fileHandle.close();
214 }
215
ProcessModuleExecuteTime()216 void ModuleLogger::ProcessModuleExecuteTime()
217 {
218 RuntimeLockHolder locker(vm_->GetJSThread(), mutex_);
219 totalFileNumber_ = jsModuleLoadInfo_.size();
220 double totalTime = 0;
221 double usedFileTime = 0;
222 double unusedFileTime = 0;
223 for (auto &i : jsModuleLoadInfo_) {
224 ModuleLoadInfo *info = i.second;
225 double time = info->time;
226 if (info->isUsed) {
227 usedFileNumber_++;
228 usedFileTime += time;
229 } else {
230 unusedFileNumber_++;
231 unusedFileTime += time;
232 }
233 totalTime += time;
234 }
235 totalTime_ = static_cast<int64_t>(totalTime);
236 usedFileTime_ = static_cast<int64_t>(usedFileTime);
237 unusedFileTime_ = static_cast<int64_t>(unusedFileTime);
238 }
239
GetModuleLoadInfo(const CString & recordName)240 ModuleLoadInfo *ModuleLogger::GetModuleLoadInfo(const CString &recordName)
241 {
242 auto info = jsModuleLoadInfo_.find(recordName);
243 if (info != jsModuleLoadInfo_.end()) {
244 return info->second;
245 }
246 ModuleLoadInfo *newInfo = new ModuleLoadInfo();
247 jsModuleLoadInfo_.emplace(recordName, newInfo);
248 return newInfo;
249 }
250
SetStartTime(const CString & recordName)251 void ModuleLogger::SetStartTime(const CString &recordName)
252 {
253 // func_main_0/_GLOBAL::func_main_0 is system abc or so js/abc, need to exclude.
254 if (recordName == ModulePathHelper::ENTRY_FUNCTION_NAME ||
255 recordName == ModulePathHelper::ENTRY_MAIN_FUNCTION) {
256 return;
257 }
258 RuntimeLockHolder locker(vm_->GetJSThread(), mutex_);
259 ModuleLoadInfo *info = GetModuleLoadInfo(recordName);
260 info->time = std::chrono::duration_cast<std::chrono::microseconds>
261 (std::chrono::high_resolution_clock::now().time_since_epoch()).count();
262 }
263
SetEndTime(const CString & recordName)264 void ModuleLogger::SetEndTime(const CString &recordName)
265 {
266 // func_main_0/_GLOBAL::func_main_0 is system abc or so js/abc, need to exclude.
267 if (recordName == ModulePathHelper::ENTRY_FUNCTION_NAME ||
268 recordName == ModulePathHelper::ENTRY_MAIN_FUNCTION) {
269 return;
270 }
271 RuntimeLockHolder locker(vm_->GetJSThread(), mutex_);
272 ModuleLoadInfo *info = GetModuleLoadInfo(recordName);
273 double time = info->time;
274 info->time = (std::chrono::duration_cast<std::chrono::microseconds>
275 (std::chrono::high_resolution_clock::now().time_since_epoch())
276 .count() - time) / DOUBLE_MILLISECONDS_PER_SEC;
277 }
278
ToStringWithPrecision(const double num,const uint8_t n)279 std::string ModuleLogger::ToStringWithPrecision(const double num, const uint8_t n)
280 {
281 std::ostringstream out;
282 out << std::setprecision(n) << num;
283 return out.str();
284 }
285
PrintModuleLoadInfoTask(void * data)286 void ModuleLogger::PrintModuleLoadInfoTask(void *data)
287 {
288 ModuleLogger* moduleLogger = static_cast<ModuleLogger*>(data);
289 if (moduleLogger == nullptr) {
290 return;
291 }
292 moduleLogger->PrintModuleLoadInfo();
293 }
294
SetModuleLoggerTask(EcmaVM * vm)295 void ModuleLogger::SetModuleLoggerTask(EcmaVM *vm)
296 {
297 ModuleLogger *moduleLogger = vm->GetJSThread()->GetCurrentEcmaContext()->GetModuleLogger();
298 if (moduleLogger == nullptr) {
299 return;
300 }
301 TimerTaskCallback timerTaskCallBack = vm->GetTimerTaskCallback();
302 if (timerTaskCallBack == nullptr) {
303 LOG_FULL(ERROR) << "TimerTaskCallback is nullptr";
304 return;
305 }
306 uint64_t importDurationInMs = GetImportDuration(TWO_SECONDS);
307 timerTaskCallBack(vm, moduleLogger, PrintModuleLoadInfoTask, importDurationInMs, 0);
308 }
309 } // namespace panda::ecmascript
310