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