1 /*
2  * Copyright (c) 2020-2021 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 "js_profiler.h"
17 // invoked into compiling only if performance measurement enabled
18 #if IS_ENABLED(JS_PROFILER)
19 #include "ace_log.h"
20 #include "ace_mem_base.h"
21 #include "js_async_work.h"
22 #include "js_fwk_common.h"
23 #include "key_parser.h"
24 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
25 #include <fcntl.h>
26 #include "los_tick.h"
27 #include "unistd.h"
28 
29 #elif (FEATURE_ACELITE_JS_PROFILER == 1)
30 #include <sys/time.h>
31 #else
32 #include <time.h>
33 #endif // FEATURE_ACELITE_MC_JS_PROFILER
34 #include "securec.h"
35 #include <stdlib.h>
36 
37 namespace OHOS {
38 namespace ACELite {
39 /**
40  * Global instance, will be initialized when the first call of JSProfiler::GetInstance().
41  */
42 
43 static bool g_isFirst = true;
44 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
45 static uint16_t g_profiler_msg_index = 0;
46 #else
47 static constexpr uint8_t PHASE_NAME_LENGTH = 50;
48 #endif
49 
50 struct ProfilerPhase {
51     uint8_t phaseId;
52 #ifndef FEATURE_ACELITE_MC_JS_PROFILER
53     char phaseName[PHASE_NAME_LENGTH];
54 #endif
55     PerformanceTag parentPhase;
56 };
57 
58 /**
59  * Use static const strings other than accepting strings from tracing apis's caller,
60  * as that will need to do the string copy, which may make the cost bigger.
61  * NOTE: Keep this array sync with PerformanceTag definations
62  */
63 static const ProfilerPhase g_profilerPhaseConfig[] = {
64 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
65     // id, parent
66     {P_UNKNOWN, P_UNKNOWN},
67     {LAUNCH, P_UNKNOWN},
68     {ENGINE_INIT, LAUNCH},
69     {FWK_INIT, LAUNCH},
70     {JS_BEGIN, P_UNKNOWN},
71     {JS_FWK_EVAL, PAGE_CODE_EVAL},
72     {JS_APP_INIT, FWK_CODE_EVAL},
73     {JS_INIT_STATE, JS_FWK_EVAL},
74     {JS_INIT_DATA_GET_DATA, JS_INIT_STATE},
75     {JS_INIT_DATA_PROXY, JS_INIT_STATE},
76     {JS_INIT_DATA_OBSERVE, JS_INIT_STATE},
77     {JS_END, P_UNKNOWN},
78     {FWK_CODE_LOAD, FWK_INIT},
79     {FWK_CODE_EVAL, FWK_INIT},
80     {APP_CODE_LOAD, LAUNCH},
81     {APP_CODE_EVAL, LAUNCH},
82     {PAGE_CODE_LOAD, ROUTER_REPLACE},
83     {PAGE_CODE_EVAL, ROUTER_REPLACE},
84     {STYLESHEET_INIT, JS_FWK_EVAL},
85     {APP_ON_CREATE, LAUNCH},
86     {APP_ON_DESTROY, LAUNCH},
87     {ROUTER_REPLACE, LAUNCH},
88     {PAGE_TRANSFER_DATA, ROUTER_REPLACE},
89     {PAGE_ON_INIT, ROUTER_REPLACE},
90     {PAGE_ON_READY, ROUTER_REPLACE},
91     {PAGE_ON_SHOW, ROUTER_REPLACE},
92     {PAGE_ON_BACKGROUND, ROUTER_REPLACE},
93     {PAGE_ON_DESTROY, P_UNKNOWN},
94     {RENDER, ROUTER_REPLACE},
95     {ADD_TO_ROOT_VIEW, LAUNCH},
96     {RENDER_CREATE_COMPONENT, RENDER},
97     {RENDER_COMBINE_STYLE, RENDER},
98     {RENDER_BIND_JS_OBJECT, RENDER},
99     {RENDER_PARSE_ATTR, RENDER},
100     {RENDER_PARSE_EVENT, RENDER},
101     {RENDER_APPLY_STYLE, RENDER},
102     {RENDER_PROCESS_CHILDREN, RENDER},
103     {SET_ATTR_PARSE_EXPRESSION, RENDER_PARSE_ATTR},
104     {SET_ATTR_STRING_OF, RENDER_PARSE_ATTR},
105     {SET_ATTR_PARSE_KEY_ID, RENDER_PARSE_ATTR},
106     {SET_ATTR_SET_TO_NATIVE, RENDER_PARSE_ATTR},
107     {APPLY_STYLE_ITEM, RENDER_APPLY_STYLE},
108     {WATCHER_CALLBACK_FUNC, P_UNKNOWN},
109     {FOR_WATCHER_CALLBACK_FUNC, P_UNKNOWN},
110     {WATCHER_CONSTRUCT, SET_ATTR_PARSE_EXPRESSION}
111 #else
112     // id, name, parent
113     {P_UNKNOWN, "UNKNOWN", P_UNKNOWN},
114     {LAUNCH, "LAUNCH", P_UNKNOWN},
115     {ENGINE_INIT, "ENGINE_INIT", LAUNCH},
116     {FWK_INIT, "FWK_INIT", LAUNCH},
117     {JS_BEGIN, "JS_BEGIN", P_UNKNOWN},                               // not used
118     {JS_FWK_EVAL, "JS_FWK_EVAL", PAGE_CODE_EVAL},                    // 5
119     {JS_APP_INIT, "JS_APP_INIT", FWK_CODE_EVAL},                     // 6
120     {JS_INIT_STATE, "JS_INIT_STATE", JS_FWK_EVAL},                   // 7
121     {JS_INIT_DATA_GET_DATA, "JS_INIT_DATA_GET_DATA", JS_INIT_STATE}, // 8
122     {JS_INIT_DATA_PROXY, "JS_INIT_DATA_PROXY", JS_INIT_STATE},       // 9
123     {JS_INIT_DATA_OBSERVE, "JS_INIT_DATA_OBSERVE", JS_INIT_STATE},   // 10
124     {JS_END, "JS_END", P_UNKNOWN},                                   // not used
125     {FWK_CODE_LOAD, "FWK_CODE_LOAD", FWK_INIT},
126     {FWK_CODE_EVAL, "FWK_CODE_EVAL", FWK_INIT},
127     {APP_CODE_LOAD, "APP_CODE_LOAD", LAUNCH},
128     {APP_CODE_EVAL, "APP_CODE_EVAL", LAUNCH},
129     {PAGE_CODE_LOAD, "PAGE_CODE_LOAD", ROUTER_REPLACE},
130     {PAGE_CODE_EVAL, "PAGE_CODE_EVAL", ROUTER_REPLACE},
131     {STYLESHEET_INIT, "STYLESHEET_INIT", JS_FWK_EVAL},
132     {APP_ON_CREATE, "APP_ON_CREATE", LAUNCH},
133     {APP_ON_DESTROY, "APP_ON_DESTROY", LAUNCH},
134     {ROUTER_REPLACE, "ROUTER_REPLACE", LAUNCH},
135     {PAGE_TRANSFER_DATA, "PAGE_TRANSFER_DATA", ROUTER_REPLACE},
136     {PAGE_ON_INIT, "PAGE_ON_INIT", ROUTER_REPLACE},
137     {PAGE_ON_READY, "PAGE_ON_READY", ROUTER_REPLACE},
138     {PAGE_ON_SHOW, "PAGE_ON_SHOW", ROUTER_REPLACE},
139     {PAGE_ON_BACKGROUND, "PAGE_ON_BACKGROUND", ROUTER_REPLACE},
140     {PAGE_ON_DESTROY, "PAGE_ON_DESTROY", P_UNKNOWN},
141     {RENDER, "RENDER", ROUTER_REPLACE},
142     {ADD_TO_ROOT_VIEW, "ADD_TO_ROOT_VIEW", LAUNCH},
143     {RENDER_CREATE_COMPONENT, "RENDER_CREATE_COMPONENT", RENDER},
144     {RENDER_COMBINE_STYLE, "RENDER_COMBINE_STYLE", RENDER},
145     {RENDER_BIND_JS_OBJECT, "RENDER_BIND_JS_OBJECT", RENDER},
146     {RENDER_PARSE_ATTR, "RENDER_PARSE_ATTR", RENDER},
147     {RENDER_PARSE_EVENT, "RENDER_PARSE_EVENT", RENDER},
148     {RENDER_APPLY_STYLE, "RENDER_APPLY_STYLE", RENDER},
149     {RENDER_PROCESS_CHILDREN, "RENDER_PROCESS_CHILDREN", RENDER},
150     {SET_ATTR_PARSE_EXPRESSION, "SET_ATTR_PARSE_EXPRESSION", RENDER_PARSE_ATTR},
151     {SET_ATTR_STRING_OF, "SET_ATTR_STRING_OF", RENDER_PARSE_ATTR},
152     {SET_ATTR_PARSE_KEY_ID, "SET_ATTR_PARSE_KEY_ID", RENDER_PARSE_ATTR},
153     {SET_ATTR_SET_TO_NATIVE, "SET_ATTR_SET_TO_NATIVE", RENDER_PARSE_ATTR},
154     {APPLY_STYLE_ITEM, "APPLY_STYLE_ITEM", RENDER_APPLY_STYLE},
155     {WATCHER_CALLBACK_FUNC, "WATCHER_CALLBACK_FUNC", P_UNKNOWN},
156     {FOR_WATCHER_CALLBACK_FUNC, "FOR_WATCHER_CALLBACK_FUNC", P_UNKNOWN},
157     {WATCHER_CONSTRUCT, "WATCHER_CONSTRUCT", SET_ATTR_PARSE_EXPRESSION}
158 #endif
159 };
160 
161 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
JSProfiler()162 JSProfiler::JSProfiler() : data_(nullptr), dataCount_(0), traceIdSlot_(0), enabled_(false), msg_(nullptr) {}
163 #else
JSProfiler()164 JSProfiler::JSProfiler() : data_(nullptr), dataCount_(0), traceIdSlot_(0), enabled_(false) {}
165 #endif
166 
~JSProfiler()167 JSProfiler::~JSProfiler() {}
168 
GetInstance()169 JSProfiler *JSProfiler::GetInstance()
170 {
171     static JSProfiler profilerInstance;
172     return &profilerInstance;
173 }
174 
IsEnabled()175 bool JSProfiler::IsEnabled()
176 {
177     bool isEnabled = enabled_ && (data_ != nullptr);
178 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
179     isEnabled = isEnabled && (msg_ != nullptr);
180 #endif
181     return isEnabled;
182 }
183 
PrepareDataBuffer()184 void JSProfiler::PrepareDataBuffer()
185 {
186     enabled_ = IsFileExisted(PROFILER_ENABLE_FLAG_FILE);
187     if (!enabled_) {
188         return;
189     }
190     data_ = static_cast<PerformanceData *>(ace_malloc(maxTracingDataCount * sizeof(PerformanceData)));
191     if (data_ == nullptr) {
192         HILOG_ERROR(HILOG_MODULE_ACE, "malloc performance data buffer failed");
193         return;
194     }
195 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
196     msg_ = static_cast<ProfilerMsg *>(ace_malloc(PROFILER_MSG_LENGTH * sizeof(ProfilerMsg)));
197     if (msg_ == nullptr) {
198         HILOG_ERROR(HILOG_MODULE_ACE, "malloc performance data buffer failed");
199         ace_free(data_);
200         data_ = nullptr;
201         return;
202     }
203 #endif
204     ResetData();
205 }
206 
207 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
FlushProfilerMsg(void * data)208 void JSProfiler::FlushProfilerMsg(void *data)
209 {
210     if (data == nullptr) {
211         HILOG_ERROR(HILOG_MODULE_ACE, "sync js profiler msg error");
212         return;
213     }
214 
215     uint32_t timestamp = JSProfiler::GetInstance()->GetCurrentClockTick();
216     char fileName[TEXT_LENGTH] = {'\0'};
217     if (sprintf_s(fileName, TEXT_LENGTH, "ace_profiler_%d.log", timestamp) < 0) {
218         HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler flushmsg sprintf error");
219         return;
220     }
221 
222     char *fullPath = RelocateJSSourceFilePath(DEFAULT_PROFILER_MSG_PATH, fileName);
223     if (fullPath == nullptr) {
224         HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler create error");
225         return;
226     }
227 
228     int32_t fd = open(fullPath, O_CREAT | O_RDWR, S_IRUSR | S_IWUSR);
229     if (fd < 0) {
230         HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler open error");
231         ace_free(fullPath);
232         fullPath = nullptr;
233         return;
234     }
235 
236     for (uint16_t i = 0; i < g_profiler_msg_index; i++) {
237         if (write(fd, JSProfiler::GetInstance()->msg_[i].msg, strlen(JSProfiler::GetInstance()->msg_[i].msg)) < 0) {
238             HILOG_ERROR(HILOG_MODULE_ACE, "ace dump js profiler msg error");
239             break;
240         }
241     }
242 
243     if (close(fd) < 0) {
244         HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler close error");
245     }
246 
247     ace_free(fullPath);
248     fullPath = nullptr;
249     g_profiler_msg_index = 0;
250     JSProfiler::GetInstance()->ResetData();
251 }
252 #endif
253 
Release()254 void JSProfiler::Release()
255 {
256     ACE_FREE(data_);
257 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
258     ACE_FREE(msg_);
259 #endif
260 }
261 
ResetData()262 void JSProfiler::ResetData()
263 {
264     if (data_) {
265         if (memset_s(data_, (maxTracingDataCount * sizeof(PerformanceData)), 0,
266                      (maxTracingDataCount * sizeof(PerformanceData))) != 0) {
267             HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler memset_s failed");
268             return;
269         }
270     }
271 
272 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
273     if (msg_) {
274         if (memset_s(msg_, (PROFILER_MSG_LENGTH * sizeof(ProfilerMsg)), 0,
275                      (PROFILER_MSG_LENGTH * sizeof(ProfilerMsg))) != 0) {
276             HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler memset_s failed");
277             return;
278         }
279     }
280 #endif
281     dataCount_ = 0;
282     g_isFirst = true;
283 }
284 
285 static uint64_t g_startOffset = 0;
PushTrace(PerformanceTag tag,uint8_t name,uint8_t description)286 void JSProfiler::PushTrace(PerformanceTag tag, uint8_t name, uint8_t description)
287 {
288     if (!IsEnabled()) {
289         return;
290     }
291 
292     // skip some redundant modules
293     if (g_isFirst) {
294         if ((tag != LAUNCH) && (tag != ROUTER_REPLACE)) {
295             return;
296         }
297         g_isFirst = false;
298     }
299 
300     if (g_startOffset == 0) {
301         g_startOffset = GetCurrentClockTick();
302     }
303     if (traceIdSlot_ >= maxCountAllAtOnce) {
304         // the trace id is running out, can not process this tracing request util any STOP_TRACING called
305         return;
306     }
307 
308     if (dataCount_ >= maxTracingDataCount) {
309         return;
310     }
311 
312     uint16_t dataIndex = dataCount_;
313     // record current time stamp
314     data_[dataIndex].start = GetCurrentClockTick() - g_startOffset;
315     data_[dataIndex].label = tag;
316     data_[dataIndex].component = name;
317     data_[dataIndex].description = description;
318 
319     // record the new trace id into stack
320     traceIdStack_[traceIdSlot_] = dataIndex;
321     traceIdSlot_++;
322     // increase data count
323     dataCount_++;
324 }
325 
326 /**
327  * @brief Calculate time cost and output to trace.
328  */
PopTrace()329 void JSProfiler::PopTrace()
330 {
331     if (!IsEnabled()) {
332         return;
333     }
334     if ((traceIdSlot_ == 0) || (traceIdSlot_ > maxCountAllAtOnce)) {
335         return;
336     }
337     uint16_t traceId = traceIdStack_[traceIdSlot_ - 1];
338     traceIdSlot_--;
339     data_[traceId].end = GetCurrentClockTick() - g_startOffset;
340 }
341 
Output()342 void JSProfiler::Output()
343 {
344     if (!IsEnabled()) {
345         return;
346     }
347     for (uint16_t dataIndex = 0; dataIndex < dataCount_; dataIndex++) {
348         PerformanceData data = data_[dataIndex];
349         if ((data.label > ADD_TO_ROOT_VIEW) && (data.start >= data.end)) {
350             // for too many round details, we just print out bigger than 0 items to save the log IO band width
351             continue;
352         }
353 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
354         if (g_profiler_msg_index == 0) {
355             if ((data.label != LAUNCH) && (data.label != ROUTER_REPLACE)) {
356                 continue;
357             }
358         }
359 
360         if (g_profiler_msg_index >= PROFILER_MSG_LENGTH) {
361             continue;
362         }
363 
364         char buf[MSG_LENGTH] = {'\0'};
365         if (sprintf_s(buf, MSG_LENGTH, "%d %d %llu %d %d\n", data.component, data.label,
366                       CalculateElapsedTime(data.start, data.end), data.description, data.label) < 0) {
367             HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler memset_s msg failed");
368             return;
369         }
370         if (strcpy_s(msg_[g_profiler_msg_index].msg, MSG_LENGTH, buf) != 0) {
371             HILOG_ERROR(HILOG_MODULE_ACE, "ace js profiler write msg failed");
372             return;
373         }
374         g_profiler_msg_index++;
375 
376 #else
377         LOG_PROFILER("COST %s %s %llu ms [%s] %s", KeyParser::GetKeyById(data.component),
378                      g_profilerPhaseConfig[data.label].phaseName, CalculateElapsedTime(data.start, data.end),
379                      (data.description != 0) ? KeyParser::GetKeyById(data.description) : "",
380                      g_profilerPhaseConfig[g_profilerPhaseConfig[data.label].parentPhase].phaseName);
381 #endif
382     }
383 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
384     JsAsyncWork::DispatchAsyncWork(FlushProfilerMsg, this);
385 #else
386     // reset all records after output to trace
387     ResetData();
388 #endif
389 }
390 
GetCurrentClockTick() const391 uint64_t JSProfiler::GetCurrentClockTick() const
392 {
393 #if (FEATURE_ACELITE_MC_JS_PROFILER == 1)
394     // real device
395     return LOS_TickCountGet(); // count in clock ticks, usually is ms
396 #elif (FEATURE_ACELITE_JS_PROFILER == 1)
397     const uint32_t unit = 1000;
398     // ipcamera
399     struct timeval timeVal;
400     struct timezone timeZone;
401     return (gettimeofday(&timeVal, &timeZone) == 0) ? ((timeVal.tv_usec / unit) + (timeVal.tv_sec * unit)) : 0;
402 #else
403     // PC simulator
404     return clock(); // count in clock ticks, usually is ms
405 #endif
406 }
407 
408 // convert clock tick intervals into milliseconds
CalculateElapsedTime(uint64_t start,uint64_t end) const409 uint64_t JSProfiler::CalculateElapsedTime(uint64_t start, uint64_t end) const
410 {
411     if (start >= end) {
412         return 0;
413     }
414 
415     uint64_t interval = end - start;
416 #if ((FEATURE_ACELITE_MC_JS_PROFILER == 1) || (FEATURE_ACELITE_JS_PROFILER == 1))
417     // real device
418     return interval;
419 #else
420     // PC simulator
421     const uint32_t msPerSec = 1000;
422     return (interval * msPerSec) / CLOCKS_PER_SEC;
423 #endif
424 }
425 } // namespace ACELite
426 } // namespace OHOS
427 #endif // ENABLED(JS_PROFILER)
428