1 /*
2 * Copyright (C) 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 <atomic>
17 #include <cinttypes>
18 #include <climits>
19 #include <ctime>
20 #include <fcntl.h>
21 #include <fstream>
22 #include <mutex>
23 #include <unistd.h>
24 #include <vector>
25 #include "securec.h"
26 #include "hilog/log.h"
27 #include "param/sys_param.h"
28 #include "parameter.h"
29 #include "parameters.h"
30 #include "hitrace_meter.h"
31 #include "hitrace/tracechain.h"
32
33 using namespace std;
34 using namespace OHOS::HiviewDFX;
35
36 #define EXPECTANTLY(exp) (__builtin_expect(!!(exp), true))
37 #define UNEXPECTANTLY(exp) (__builtin_expect(!!(exp), false))
38 #define UNUSED_PARAM __attribute__((__unused__))
39
40 namespace {
41 int g_markerFd = -1;
42 std::once_flag g_onceFlag;
43 std::once_flag g_onceWriteMarkerFailedFlag;
44 CachedHandle g_cachedHandle;
45
46 std::atomic<bool> g_isHitraceMeterDisabled(false);
47 std::atomic<bool> g_isHitraceMeterInit(false);
48 std::atomic<uint64_t> g_tagsProperty(HITRACE_TAG_NOT_READY);
49
50 const std::string KEY_TRACE_TAG = "debug.hitrace.tags.enableflags";
51 const std::string KEY_APP_NUMBER = "debug.hitrace.app_number";
52 const std::string KEY_RO_DEBUGGABLE = "ro.debuggable";
53 const std::string KEY_PREFIX = "debug.hitrace.app_";
54
55 constexpr int VAR_NAME_MAX_SIZE = 400;
56 constexpr int NAME_NORMAL_LEN = 512;
57 constexpr int BUFFER_LEN = 640;
58 constexpr int HITRACEID_LEN = 64;
59
60 static const int PID_BUF_SIZE = 6;
61 static char g_pid[PID_BUF_SIZE];
62 static const std::string EMPTY_TRACE_NAME;
63
64 static char g_markTypes[5] = {'B', 'E', 'S', 'F', 'C'};
65 enum MarkerType { MARKER_BEGIN, MARKER_END, MARKER_ASYNC_BEGIN, MARKER_ASYNC_END, MARKER_INT, MARKER_MAX };
66
67 #undef LOG_DOMAIN
68 #define LOG_DOMAIN 0xD002D33
69
70 #undef LOG_TAG
71 #define LOG_TAG "HitraceMeter"
72
CreateCacheHandle()73 inline void CreateCacheHandle()
74 {
75 const char* devValue = "true";
76 g_cachedHandle = CachedParameterCreate(KEY_TRACE_TAG.c_str(), devValue);
77 }
78
UpdateSysParamTags()79 inline void UpdateSysParamTags()
80 {
81 // Get the system parameters of KEY_TRACE_TAG.
82 int changed = 0;
83 if (UNEXPECTANTLY(g_cachedHandle == nullptr)) {
84 CreateCacheHandle();
85 HILOG_ERROR(LOG_CORE, "g_cachedHandle is null.");
86 return;
87 }
88 const char *paramValue = CachedParameterGetChanged(g_cachedHandle, &changed);
89 if (UNEXPECTANTLY(changed == 1) && paramValue != nullptr) {
90 uint64_t tags = 0;
91 tags = strtoull(paramValue, nullptr, 0);
92 g_tagsProperty = (tags | HITRACE_TAG_ALWAYS) & HITRACE_TAG_VALID_MASK;
93 }
94 }
95
96 // open file "trace_marker".
OpenTraceMarkerFile()97 void OpenTraceMarkerFile()
98 {
99 const std::string debugFile = "/sys/kernel/debug/tracing/trace_marker";
100 const std::string traceFile = "/sys/kernel/tracing/trace_marker";
101 g_markerFd = open(debugFile.c_str(), O_WRONLY | O_CLOEXEC);
102 if (g_markerFd == -1) {
103 HILOG_ERROR(LOG_CORE, "open trace file %{public}s failed: %{public}d", debugFile.c_str(), errno);
104 g_markerFd = open(traceFile.c_str(), O_WRONLY | O_CLOEXEC);
105 if (g_markerFd == -1) {
106 HILOG_ERROR(LOG_CORE, "open trace file %{public}s failed: %{public}d", traceFile.c_str(), errno);
107 g_tagsProperty = 0;
108 return;
109 }
110 }
111 // get tags and pid
112 g_tagsProperty = OHOS::system::GetUintParameter<uint64_t>(KEY_TRACE_TAG, 0);
113 CreateCacheHandle();
114
115 std::string pidStr = std::to_string(getprocpid());
116 errno_t ret = strcpy_s(g_pid, PID_BUF_SIZE, pidStr.c_str());
117 if (ret != 0) {
118 strcpy_s(g_pid, PID_BUF_SIZE, pidStr.c_str());
119 }
120 HILOG_ERROR(LOG_CORE, "pid[%{public}s] first get g_tagsProperty: %{public}s", pidStr.c_str(),
121 to_string(g_tagsProperty.load()).c_str());
122
123 g_isHitraceMeterInit = true;
124 }
125
WriteFailedLog()126 void WriteFailedLog()
127 {
128 HILOG_ERROR(LOG_CORE, "write trace_marker failed, %{public}d", errno);
129 }
130
WriteToTraceMarker(const char * buf,const int count)131 void WriteToTraceMarker(const char* buf, const int count)
132 {
133 if (UNEXPECTANTLY(count <= 0)) {
134 return;
135 }
136 if (UNEXPECTANTLY(count >= BUFFER_LEN)) {
137 return;
138 }
139 if (write(g_markerFd, buf, count) < 0) {
140 std::call_once(g_onceWriteMarkerFailedFlag, WriteFailedLog);
141 }
142 }
143
AddTraceMarkerLarge(const std::string & name,MarkerType type,const int64_t value)144 void AddTraceMarkerLarge(const std::string& name, MarkerType type, const int64_t value)
145 {
146 std::string record;
147 record += g_markTypes[type];
148 record += "|";
149 record += g_pid;
150 record += "|H:";
151 HiTraceId hiTraceId = HiTraceChain::GetId();
152 if (hiTraceId.IsValid()) {
153 char buf[HITRACEID_LEN] = {0};
154 int bytes = snprintf_s(buf, sizeof(buf), sizeof(buf) - 1, "[%llx,%llx,%llx]#",
155 hiTraceId.GetChainId(), hiTraceId.GetSpanId(), hiTraceId.GetParentSpanId());
156 if (EXPECTANTLY(bytes > 0)) {
157 record += buf;
158 }
159 }
160 record += name;
161 record += " ";
162 if (value != 0) {
163 record += std::to_string(value);
164 }
165 WriteToTraceMarker(record.c_str(), record.size());
166 }
167
AddHitraceMeterMarker(MarkerType type,uint64_t tag,const std::string & name,const int64_t value)168 void AddHitraceMeterMarker(MarkerType type, uint64_t tag, const std::string& name, const int64_t value)
169 {
170 if (UNEXPECTANTLY(g_isHitraceMeterDisabled)) {
171 return;
172 }
173 if (UNEXPECTANTLY(!g_isHitraceMeterInit)) {
174 struct timespec ts = { 0, 0 };
175 if (clock_gettime(CLOCK_MONOTONIC, &ts) == -1 || ts.tv_sec < 25) { // 25 : register after boot 25s
176 return;
177 }
178 std::call_once(g_onceFlag, OpenTraceMarkerFile);
179 }
180 UpdateSysParamTags();
181 if (UNEXPECTANTLY(g_tagsProperty & tag) && g_markerFd != -1) {
182 // record fomart: "type|pid|name value".
183 char buf[BUFFER_LEN] = {0};
184 int len = name.length();
185 if (UNEXPECTANTLY(len <= NAME_NORMAL_LEN)) {
186 HiTraceId hiTraceId = HiTraceChain::GetId();
187 bool isHiTraceIdValid = hiTraceId.IsValid();
188 int bytes = 0;
189 if (type == MARKER_BEGIN) {
190 bytes = isHiTraceIdValid ? snprintf_s(buf, sizeof(buf), sizeof(buf) - 1,
191 "B|%s|H:[%llx,%llx,%llx]#%s ", g_pid, hiTraceId.GetChainId(),
192 hiTraceId.GetSpanId(), hiTraceId.GetParentSpanId(), name.c_str())
193 : snprintf_s(buf, sizeof(buf), sizeof(buf) - 1, "B|%s|H:%s ", g_pid, name.c_str());
194 } else if (type == MARKER_END) {
195 bytes = snprintf_s(buf, sizeof(buf), sizeof(buf) - 1,
196 "E|%s|", g_pid);
197 } else {
198 char marktypestr = g_markTypes[type];
199 bytes = isHiTraceIdValid ? snprintf_s(buf, sizeof(buf), sizeof(buf) - 1,
200 "%c|%s|H:[%llx,%llx,%llx]#%s %lld", marktypestr, g_pid,
201 hiTraceId.GetChainId(), hiTraceId.GetSpanId(), hiTraceId.GetParentSpanId(), name.c_str(), value)
202 : snprintf_s(buf, sizeof(buf), sizeof(buf) - 1,
203 "%c|%s|H:%s %lld", marktypestr, g_pid, name.c_str(), value);
204 }
205 WriteToTraceMarker(buf, bytes);
206 } else {
207 AddTraceMarkerLarge(name, type, value);
208 }
209 }
210 }
211 }; // namespace
212
UpdateTraceLabel()213 void UpdateTraceLabel()
214 {
215 if (!g_isHitraceMeterInit) {
216 return;
217 }
218 UpdateSysParamTags();
219 }
220
SetTraceDisabled(bool disable)221 void SetTraceDisabled(bool disable)
222 {
223 g_isHitraceMeterDisabled = disable;
224 }
225
StartTraceWrapper(uint64_t label,const char * value)226 void StartTraceWrapper(uint64_t label, const char *value)
227 {
228 std::string traceValue = value;
229 StartTrace(label, traceValue);
230 }
231
StartTrace(uint64_t label,const string & value,float limit UNUSED_PARAM)232 void StartTrace(uint64_t label, const string& value, float limit UNUSED_PARAM)
233 {
234 AddHitraceMeterMarker(MARKER_BEGIN, label, value, 0);
235 }
236
StartTraceDebug(bool isDebug,uint64_t label,const string & value,float limit UNUSED_PARAM)237 void StartTraceDebug(bool isDebug, uint64_t label, const string& value, float limit UNUSED_PARAM)
238 {
239 if (!isDebug) {
240 return;
241 }
242 AddHitraceMeterMarker(MARKER_BEGIN, label, value, 0);
243 }
244
StartTraceArgs(uint64_t label,const char * fmt,...)245 void StartTraceArgs(uint64_t label, const char *fmt, ...)
246 {
247 char name[VAR_NAME_MAX_SIZE] = { 0 };
248 va_list args;
249 va_start(args, fmt);
250 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
251 va_end(args);
252 if (res < 0) {
253 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
254 return;
255 }
256 AddHitraceMeterMarker(MARKER_BEGIN, label, name, 0);
257 }
258
StartTraceArgsDebug(bool isDebug,uint64_t label,const char * fmt,...)259 void StartTraceArgsDebug(bool isDebug, uint64_t label, const char *fmt, ...)
260 {
261 if (!isDebug) {
262 return;
263 }
264 char name[VAR_NAME_MAX_SIZE] = { 0 };
265 va_list args;
266
267 va_start(args, fmt);
268 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
269 va_end(args);
270 if (res < 0) {
271 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
272 return;
273 }
274 AddHitraceMeterMarker(MARKER_BEGIN, label, name, 0);
275 }
276
FinishTrace(uint64_t label)277 void FinishTrace(uint64_t label)
278 {
279 AddHitraceMeterMarker(MARKER_END, label, EMPTY_TRACE_NAME, 0);
280 }
281
FinishTraceDebug(bool isDebug,uint64_t label)282 void FinishTraceDebug(bool isDebug, uint64_t label)
283 {
284 if (!isDebug) {
285 return;
286 }
287 AddHitraceMeterMarker(MARKER_END, label, EMPTY_TRACE_NAME, 0);
288 }
289
StartAsyncTrace(uint64_t label,const string & value,int32_t taskId,float limit UNUSED_PARAM)290 void StartAsyncTrace(uint64_t label, const string& value, int32_t taskId, float limit UNUSED_PARAM)
291 {
292 AddHitraceMeterMarker(MARKER_ASYNC_BEGIN, label, value, taskId);
293 }
294
StartAsyncTraceWrapper(uint64_t label,const char * value,int32_t taskId)295 void StartAsyncTraceWrapper(uint64_t label, const char *value, int32_t taskId)
296 {
297 std::string traceValue = value;
298 StartAsyncTrace(label, traceValue, taskId);
299 }
300
StartAsyncTraceDebug(bool isDebug,uint64_t label,const string & value,int32_t taskId,float limit UNUSED_PARAM)301 void StartAsyncTraceDebug(bool isDebug, uint64_t label, const string& value, int32_t taskId, float limit UNUSED_PARAM)
302 {
303 if (!isDebug) {
304 return;
305 }
306 AddHitraceMeterMarker(MARKER_ASYNC_BEGIN, label, value, taskId);
307 }
308
StartAsyncTraceArgs(uint64_t label,int32_t taskId,const char * fmt,...)309 void StartAsyncTraceArgs(uint64_t label, int32_t taskId, const char *fmt, ...)
310 {
311 char name[VAR_NAME_MAX_SIZE] = { 0 };
312 va_list args;
313
314 va_start(args, fmt);
315 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
316 va_end(args);
317 if (res < 0) {
318 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
319 return;
320 }
321 AddHitraceMeterMarker(MARKER_ASYNC_BEGIN, label, name, taskId);
322 }
323
StartAsyncTraceArgsDebug(bool isDebug,uint64_t label,int32_t taskId,const char * fmt,...)324 void StartAsyncTraceArgsDebug(bool isDebug, uint64_t label, int32_t taskId, const char *fmt, ...)
325 {
326 if (!isDebug) {
327 return;
328 }
329 char name[VAR_NAME_MAX_SIZE] = { 0 };
330 va_list args;
331
332 va_start(args, fmt);
333 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
334 va_end(args);
335 if (res < 0) {
336 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
337 return;
338 }
339 AddHitraceMeterMarker(MARKER_ASYNC_BEGIN, label, name, taskId);
340 }
341
FinishAsyncTrace(uint64_t label,const string & value,int32_t taskId)342 void FinishAsyncTrace(uint64_t label, const string& value, int32_t taskId)
343 {
344 AddHitraceMeterMarker(MARKER_ASYNC_END, label, value, taskId);
345 }
346
FinishAsyncTraceWrapper(uint64_t label,const char * value,int32_t taskId)347 void FinishAsyncTraceWrapper(uint64_t label, const char *value, int32_t taskId)
348 {
349 std::string traceValue = value;
350 FinishAsyncTrace(label, traceValue, taskId);
351 }
352
FinishAsyncTraceDebug(bool isDebug,uint64_t label,const string & value,int32_t taskId)353 void FinishAsyncTraceDebug(bool isDebug, uint64_t label, const string& value, int32_t taskId)
354 {
355 if (!isDebug) {
356 return;
357 }
358 AddHitraceMeterMarker(MARKER_ASYNC_END, label, value, taskId);
359 }
360
FinishAsyncTraceArgs(uint64_t label,int32_t taskId,const char * fmt,...)361 void FinishAsyncTraceArgs(uint64_t label, int32_t taskId, const char *fmt, ...)
362 {
363 char name[VAR_NAME_MAX_SIZE] = { 0 };
364 va_list args;
365
366 va_start(args, fmt);
367 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
368 va_end(args);
369 if (res < 0) {
370 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
371 return;
372 }
373 AddHitraceMeterMarker(MARKER_ASYNC_END, label, name, taskId);
374 }
375
FinishAsyncTraceArgsDebug(bool isDebug,uint64_t label,int32_t taskId,const char * fmt,...)376 void FinishAsyncTraceArgsDebug(bool isDebug, uint64_t label, int32_t taskId, const char *fmt, ...)
377 {
378 if (!isDebug) {
379 return;
380 }
381 char name[VAR_NAME_MAX_SIZE] = { 0 };
382 va_list args;
383
384 va_start(args, fmt);
385 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
386 va_end(args);
387 if (res < 0) {
388 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
389 return;
390 }
391 AddHitraceMeterMarker(MARKER_ASYNC_END, label, name, taskId);
392 }
393
MiddleTrace(uint64_t label,const string & beforeValue UNUSED_PARAM,const std::string & afterValue)394 void MiddleTrace(uint64_t label, const string& beforeValue UNUSED_PARAM, const std::string& afterValue)
395 {
396 AddHitraceMeterMarker(MARKER_END, label, EMPTY_TRACE_NAME, 0);
397 AddHitraceMeterMarker(MARKER_BEGIN, label, afterValue, 0);
398 }
399
MiddleTraceDebug(bool isDebug,uint64_t label,const string & beforeValue UNUSED_PARAM,const std::string & afterValue)400 void MiddleTraceDebug(bool isDebug, uint64_t label, const string& beforeValue UNUSED_PARAM,
401 const std::string& afterValue)
402 {
403 if (!isDebug) {
404 return;
405 }
406 AddHitraceMeterMarker(MARKER_END, label, EMPTY_TRACE_NAME, 0);
407 AddHitraceMeterMarker(MARKER_BEGIN, label, afterValue, 0);
408 }
409
CountTrace(uint64_t label,const string & name,int64_t count)410 void CountTrace(uint64_t label, const string& name, int64_t count)
411 {
412 AddHitraceMeterMarker(MARKER_INT, label, name, count);
413 }
414
CountTraceDebug(bool isDebug,uint64_t label,const string & name,int64_t count)415 void CountTraceDebug(bool isDebug, uint64_t label, const string& name, int64_t count)
416 {
417 if (!isDebug) {
418 return;
419 }
420 AddHitraceMeterMarker(MARKER_INT, label, name, count);
421 }
422
CountTraceWrapper(uint64_t label,const char * name,int64_t count)423 void CountTraceWrapper(uint64_t label, const char *name, int64_t count)
424 {
425 std::string traceName = name;
426 CountTrace(label, traceName, count);
427 }
428
HitraceMeterFmtScoped(uint64_t label,const char * fmt,...)429 HitraceMeterFmtScoped::HitraceMeterFmtScoped(uint64_t label, const char *fmt, ...) : mTag(label)
430 {
431 char name[VAR_NAME_MAX_SIZE] = { 0 };
432 va_list args;
433
434 va_start(args, fmt);
435 int res = vsnprintf_s(name, sizeof(name), sizeof(name) - 1, fmt, args);
436 va_end(args);
437 if (res < 0) {
438 HILOG_ERROR(LOG_CORE, "vsnprintf_s failed: %{public}d", errno);
439 return;
440 }
441 AddHitraceMeterMarker(MARKER_BEGIN, label, name, 0);
442 }
443
IsTagEnabled(uint64_t tag)444 bool IsTagEnabled(uint64_t tag)
445 {
446 UpdateSysParamTags();
447 return ((tag & g_tagsProperty) == tag);
448 }
449