1 /*
2 * Copyright (C) 2023-2025 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 "performance_dumper.h"
17
18 #include "common_defs.h"
19 #include "device_auth.h"
20 #include "device_auth_defines.h"
21 #include "hc_log.h"
22 #include "hc_mutex.h"
23 #include "hc_time.h"
24 #include "hc_types.h"
25 #include "hidump_adapter.h"
26 #include "string_util.h"
27
28 #define ENABLE_PERFORMANCE_DUMPER "--enable"
29 #define DISABLE_PERFORMANCE_DUMPER "--disable"
30 #define MAX_DUMP_SESSION_NUM 10
31 #define MIN_ARGS_NUM 1
32 #define MAX_ARGS_NUM 2
33
34 IMPLEMENT_HC_VECTOR(PerformDataVec, PerformData*, 1)
35
36 static bool g_isInit = false;
37 static HcMutex *g_performDataMutex = NULL;
38 static PerformDataVec g_performDataVec;
39 static bool g_isPerformDumpEnabled = true;
40 static uint32_t g_bindClientSessionNum = 0;
41 static uint32_t g_bindServerSessionNum = 0;
42 static uint32_t g_authClientSessionNum = 0;
43 static uint32_t g_authServerSessionNum = 0;
44
CreatePerformData(void)45 static PerformData *CreatePerformData(void)
46 {
47 PerformData *performData = (PerformData *)HcMalloc(sizeof(PerformData), 0);
48 if (performData == NULL) {
49 LOGE("Failed to alloc memory for perform data!");
50 return NULL;
51 }
52 return performData;
53 }
54
DestroyPerformData(PerformData * performData)55 static void DestroyPerformData(PerformData *performData)
56 {
57 HcFree(performData);
58 }
59
ClearPerformDataVec(void)60 static void ClearPerformDataVec(void)
61 {
62 uint32_t index;
63 PerformData **performData;
64 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
65 PerformData *popData;
66 HC_VECTOR_POPELEMENT(&g_performDataVec, &popData, index);
67 DestroyPerformData(popData);
68 }
69 g_bindClientSessionNum = 0;
70 g_bindServerSessionNum = 0;
71 g_authClientSessionNum = 0;
72 g_authServerSessionNum = 0;
73 }
74
DecreaseSessionNum(PerformData * data)75 static void DecreaseSessionNum(PerformData *data)
76 {
77 if (data->isBind) {
78 if (data->isClient) {
79 g_bindClientSessionNum--;
80 } else {
81 g_bindServerSessionNum--;
82 }
83 } else {
84 if (data->isClient) {
85 g_authClientSessionNum--;
86 } else {
87 g_authServerSessionNum--;
88 }
89 }
90 }
91
RemovePerformDataIfExist(int64_t reqId)92 static void RemovePerformDataIfExist(int64_t reqId)
93 {
94 uint32_t index;
95 PerformData **performData;
96 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
97 if ((*performData)->reqId == reqId) {
98 PerformData *popData;
99 HC_VECTOR_POPELEMENT(&g_performDataVec, &popData, index);
100 DecreaseSessionNum(popData);
101 DestroyPerformData(popData);
102 return;
103 }
104 }
105 }
106
UpdateDataBySelfIndex(PerformData * performData,int64_t time)107 static void UpdateDataBySelfIndex(PerformData *performData, int64_t time)
108 {
109 switch (performData->selfIndex) {
110 case FIRST_START_TIME:
111 performData->firstTransmitTime = time;
112 performData->selfIndex = FIRST_TRANSMIT_TIME;
113 break;
114 case FIRST_TRANSMIT_TIME:
115 performData->secondStartTime = time;
116 performData->selfIndex = SECOND_START_TIME;
117 break;
118 case SECOND_START_TIME:
119 performData->secondTransmitTime = time;
120 performData->selfIndex = SECOND_TRANSMIT_TIME;
121 break;
122 case SECOND_TRANSMIT_TIME:
123 performData->thirdStartTime = time;
124 performData->selfIndex = THIRD_START_TIME;
125 break;
126 case THIRD_START_TIME:
127 performData->thirdTransmitTime = time;
128 performData->selfIndex = THIRD_TRANSMIT_TIME;
129 break;
130 case THIRD_TRANSMIT_TIME:
131 performData->fourthStartTime = time;
132 performData->selfIndex = FOURTH_START_TIME;
133 break;
134 case FOURTH_START_TIME:
135 performData->fourthTransmitTime = time;
136 performData->selfIndex = FOURTH_TRANSMIT_TIME;
137 break;
138 default:
139 LOGE("Invalid timeIndex!");
140 break;
141 }
142 }
143
UpdateDataByInputIndex(PerformData * performData,PerformTimeIndex timeIndex,int64_t time)144 static void UpdateDataByInputIndex(PerformData *performData, PerformTimeIndex timeIndex, int64_t time)
145 {
146 if (timeIndex == ON_SESSION_KEY_RETURN_TIME) {
147 performData->onSessionKeyReturnTime = time;
148 } else if (timeIndex == ON_FINISH_TIME) {
149 performData->onFinishTime = time;
150 performData->status = PERFORM_DATA_STATUS_FINISH;
151 int64_t totalTime = performData->onFinishTime - performData->firstStartTime;
152 if (performData->isBind) {
153 LOGI("Bind consume time: %" LOG_PUB PRId64 ", requestId: %" LOG_PUB PRId64, totalTime, performData->reqId);
154 } else {
155 LOGI("Auth consume time: %" LOG_PUB PRId64 ", requestId: %" LOG_PUB PRId64, totalTime, performData->reqId);
156 }
157 } else {
158 LOGE("Invalid timeIndex!");
159 }
160 }
161
GetConsumeTimeByIndex(PerformData * performData,PerformTimeIndex index)162 static int64_t GetConsumeTimeByIndex(PerformData *performData, PerformTimeIndex index)
163 {
164 switch (index) {
165 case FIRST_START_TIME:
166 if (performData->firstTransmitTime != 0) {
167 return performData->firstTransmitTime - performData->firstStartTime;
168 } else {
169 return performData->onSessionKeyReturnTime - performData->firstStartTime;
170 }
171 case SECOND_START_TIME:
172 if (performData->secondTransmitTime != 0) {
173 return performData->secondTransmitTime - performData->secondStartTime;
174 } else {
175 return performData->onSessionKeyReturnTime - performData->secondStartTime;
176 }
177 case THIRD_START_TIME:
178 if (performData->thirdTransmitTime != 0) {
179 return performData->thirdTransmitTime - performData->thirdStartTime;
180 } else {
181 return performData->onSessionKeyReturnTime - performData->thirdStartTime;
182 }
183 case FOURTH_START_TIME:
184 if (performData->fourthTransmitTime != 0) {
185 return performData->fourthTransmitTime - performData->fourthStartTime;
186 } else {
187 return performData->onSessionKeyReturnTime - performData->fourthStartTime;
188 }
189 default:
190 return 0;
191 }
192 }
193
GetOperationTag(bool isBind)194 static const char *GetOperationTag(bool isBind)
195 {
196 if (isBind) {
197 return "bind";
198 } else {
199 return "auth";
200 }
201 }
202
GetIsClientTag(bool isClient)203 static const char *GetIsClientTag(bool isClient)
204 {
205 if (isClient) {
206 return "true";
207 } else {
208 return "false";
209 }
210 }
211
DumpPerformData(int fd,PerformData * performData)212 static void DumpPerformData(int fd, PerformData *performData)
213 {
214 int64_t firstConsume = 0;
215 if (performData->firstStartTime != 0) {
216 firstConsume = GetConsumeTimeByIndex(performData, FIRST_START_TIME);
217 LOGI("firstConsume time: %" LOG_PUB PRId64 " milliseconds", firstConsume);
218 }
219 int64_t secondConsume = 0;
220 if (performData->secondStartTime != 0) {
221 secondConsume = GetConsumeTimeByIndex(performData, SECOND_START_TIME);
222 LOGI("secondConsume time: %" LOG_PUB PRId64 " milliseconds", secondConsume);
223 }
224 int64_t thirdConsume = 0;
225 if (performData->thirdStartTime != 0) {
226 thirdConsume = GetConsumeTimeByIndex(performData, THIRD_START_TIME);
227 LOGI("thirdConsume time: %" LOG_PUB PRId64 " milliseconds", thirdConsume);
228 }
229 int64_t fourthConsume = 0;
230 if (performData->fourthStartTime != 0) {
231 fourthConsume = GetConsumeTimeByIndex(performData, FOURTH_START_TIME);
232 LOGI("fourthConsume time: %" LOG_PUB PRId64 " milliseconds", fourthConsume);
233 }
234 int64_t innerConsume = firstConsume + secondConsume + thirdConsume + fourthConsume;
235 LOGI("innerConsume time: %" LOG_PUB PRId64 " milliseconds", innerConsume);
236 int64_t totalTime = performData->onFinishTime - performData->firstStartTime;
237 LOGI("totalTime time: %" LOG_PUB PRId64 " milliseconds", totalTime);
238 char reqIdStr[MAX_REQUEST_ID_LEN] = { 0 };
239 if (sprintf_s(reqIdStr, MAX_REQUEST_ID_LEN, "%lld", performData->reqId) <= 0) {
240 LOGE("Failed to get requestId string!");
241 return;
242 }
243 performData->firstConsumeTime = firstConsume;
244 performData->secondConsumeTime = secondConsume;
245 performData->thirdConsumeTime = thirdConsume;
246 performData->fourthConsumeTime = fourthConsume;
247 performData->innerConsumeTime = innerConsume;
248 performData->totalConsumeTime = totalTime;
249 const char *operationTag = GetOperationTag(performData->isBind);
250 const char *isClientTag = GetIsClientTag(performData->isClient);
251 dprintf(fd, "|%-10s|%-9s|%-10.8s|%-6lld|%-7lld|%-6lld|%-7lld|%-10lld|%-9lld|\n", operationTag, isClientTag,
252 reqIdStr, firstConsume, secondConsume, thirdConsume, fourthConsume, innerConsume, totalTime);
253 dprintf(fd, "|----------------------------------------------------------------------------------|\n");
254 }
255
GetAverageTimeTag(bool isBind,bool isClient)256 static const char *GetAverageTimeTag(bool isBind, bool isClient)
257 {
258 if (isBind) {
259 if (isClient) {
260 return "bind client average";
261 } else {
262 return "bind server average";
263 }
264 } else {
265 if (isClient) {
266 return "auth client average";
267 } else {
268 return "auth server average";
269 }
270 }
271 }
272
DumpAverageConsumeTime(int fd,bool isBind,bool isClient)273 static void DumpAverageConsumeTime(int fd, bool isBind, bool isClient)
274 {
275 int32_t sessionSize = 0;
276 int64_t totalFirstConsume = 0;
277 int64_t totalSecondConsume = 0;
278 int64_t totalThirdConsume = 0;
279 int64_t totalFourthConsume = 0;
280 int64_t totalInnerConsume = 0;
281 int64_t totalConsume = 0;
282 uint32_t index;
283 PerformData **peformData;
284 FOR_EACH_HC_VECTOR(g_performDataVec, index, peformData) {
285 if ((*peformData)->status != PERFORM_DATA_STATUS_FINISH) {
286 continue;
287 }
288 if ((*peformData)->isBind == isBind && (*peformData)->isClient == isClient) {
289 sessionSize++;
290 totalFirstConsume += (*peformData)->firstConsumeTime;
291 totalSecondConsume += (*peformData)->secondConsumeTime;
292 totalThirdConsume += (*peformData)->thirdConsumeTime;
293 totalFourthConsume += (*peformData)->fourthConsumeTime;
294 totalInnerConsume += (*peformData)->innerConsumeTime;
295 totalConsume += (*peformData)->totalConsumeTime;
296 }
297 }
298 int64_t firstAverage = 0;
299 int64_t secondAverage = 0;
300 int64_t thirdAverage = 0;
301 int64_t fourthAverage = 0;
302 int64_t innerAverage = 0;
303 int64_t totalAverage = 0;
304 if (sessionSize != 0) {
305 firstAverage = totalFirstConsume / sessionSize;
306 secondAverage = totalSecondConsume / sessionSize;
307 thirdAverage = totalThirdConsume / sessionSize;
308 fourthAverage = totalFourthConsume / sessionSize;
309 innerAverage = totalInnerConsume / sessionSize;
310 totalAverage = totalConsume / sessionSize;
311 }
312 const char *averageTimeTag = GetAverageTimeTag(isBind, isClient);
313 dprintf(fd, "|%-31s|%-6lld|%-7lld|%-6lld|%-7lld|%-10lld|%-9lld|\n", averageTimeTag, firstAverage,
314 secondAverage, thirdAverage, fourthAverage, innerAverage, totalAverage);
315 }
316
DumpDevAuthPerformData(int fd)317 static void DumpDevAuthPerformData(int fd)
318 {
319 if (!g_isPerformDumpEnabled) {
320 dprintf(fd, "performance dumper is not enabled, input the following command to enable it:\n"
321 "hidumper -s 4701 -a \"performance --enable\"\n");
322 return;
323 }
324 dprintf(fd, "|---------------------------------PerformanceData----------------------------------|\n");
325 dprintf(fd, "|%-10s|%-9s|%-10s|%-6s|%-7s|%-6s|%-7s|%-10s|%-9s|\n", "operation", "isClient", "requestId", "first",
326 "second", "third", "fourth", "innerTime", "totalTime");
327 dprintf(fd, "|----------------------------------------------------------------------------------|\n");
328 uint32_t index;
329 PerformData **peformData;
330 FOR_EACH_HC_VECTOR(g_performDataVec, index, peformData) {
331 if ((*peformData)->status != PERFORM_DATA_STATUS_FINISH) {
332 continue;
333 }
334 DumpPerformData(fd, *peformData);
335 }
336 DumpAverageConsumeTime(fd, true, true);
337 dprintf(fd, "|----------------------------------------------------------------------------------|\n");
338 DumpAverageConsumeTime(fd, true, false);
339 dprintf(fd, "|----------------------------------------------------------------------------------|\n");
340 DumpAverageConsumeTime(fd, false, true);
341 dprintf(fd, "|----------------------------------------------------------------------------------|\n");
342 DumpAverageConsumeTime(fd, false, false);
343 dprintf(fd, "|---------------------------------PerformanceData----------------------------------|\n");
344 }
345
PerformanceDump(int fd,StringVector * strArgVec)346 static void PerformanceDump(int fd, StringVector *strArgVec)
347 {
348 if (!g_isInit) {
349 LOGE("Not initialized!");
350 return;
351 }
352 (void)LockHcMutex(g_performDataMutex);
353 uint32_t argSize = strArgVec->size(strArgVec);
354 if (argSize == MIN_ARGS_NUM) {
355 DumpDevAuthPerformData(fd);
356 UnlockHcMutex(g_performDataMutex);
357 return;
358 }
359 if (argSize != MAX_ARGS_NUM) {
360 dprintf(fd, "Invalid arguments number!\n");
361 UnlockHcMutex(g_performDataMutex);
362 return;
363 }
364 HcString strArg = strArgVec->get(strArgVec, 1);
365 if (IsStrEqual(StringGet(&strArg), ENABLE_PERFORMANCE_DUMPER)) {
366 g_isPerformDumpEnabled = true;
367 dprintf(fd, "performance dumper is enabled!\n");
368 } else if (IsStrEqual(StringGet(&strArg), DISABLE_PERFORMANCE_DUMPER)) {
369 ClearPerformDataVec();
370 g_isPerformDumpEnabled = false;
371 dprintf(fd, "performance dumper is disabled!\n");
372 } else {
373 dprintf(fd, "Invalid arguments!\n");
374 }
375 UnlockHcMutex(g_performDataMutex);
376 }
377
IsSessionNumExceeded(bool isBind,bool isClient)378 static bool IsSessionNumExceeded(bool isBind, bool isClient)
379 {
380 if (isBind) {
381 if (isClient) {
382 return g_bindClientSessionNum == MAX_DUMP_SESSION_NUM;
383 } else {
384 return g_bindServerSessionNum == MAX_DUMP_SESSION_NUM;
385 }
386 } else {
387 if (isClient) {
388 return g_authClientSessionNum == MAX_DUMP_SESSION_NUM;
389 } else {
390 return g_authServerSessionNum == MAX_DUMP_SESSION_NUM;
391 }
392 }
393 }
394
IncreaseSessionNum(PerformData * data)395 static void IncreaseSessionNum(PerformData *data)
396 {
397 if (data->isBind) {
398 if (data->isClient) {
399 g_bindClientSessionNum++;
400 } else {
401 g_bindServerSessionNum++;
402 }
403 } else {
404 if (data->isClient) {
405 g_authClientSessionNum++;
406 } else {
407 g_authServerSessionNum++;
408 }
409 }
410 }
411
AddPerformData(int64_t reqId,bool isBind,bool isClient,int64_t startTime)412 void AddPerformData(int64_t reqId, bool isBind, bool isClient, int64_t startTime)
413 {
414 if (!g_isInit) {
415 return;
416 }
417 (void)LockHcMutex(g_performDataMutex);
418 if (!g_isPerformDumpEnabled) {
419 UnlockHcMutex(g_performDataMutex);
420 return;
421 }
422 RemovePerformDataIfExist(reqId);
423 if (IsSessionNumExceeded(isBind, isClient)) {
424 LOGE("session number exceeded, requestId: %" LOG_PUB PRId64, reqId);
425 UnlockHcMutex(g_performDataMutex);
426 return;
427 }
428 PerformData *performData = CreatePerformData();
429 if (performData == NULL) {
430 UnlockHcMutex(g_performDataMutex);
431 return;
432 }
433 performData->reqId = reqId;
434 performData->isBind = isBind;
435 performData->isClient = isClient;
436 performData->firstStartTime = startTime;
437 performData->selfIndex = FIRST_START_TIME;
438 performData->status = PERFORM_DATA_STATUS_BEGIN;
439 if (g_performDataVec.pushBackT(&g_performDataVec, performData) == NULL) {
440 LOGE("Failed to push perform data to vec!");
441 DestroyPerformData(performData);
442 UnlockHcMutex(g_performDataMutex);
443 return;
444 }
445 IncreaseSessionNum(performData);
446 UnlockHcMutex(g_performDataMutex);
447 }
448
ResetPerformData(int64_t reqId)449 void ResetPerformData(int64_t reqId)
450 {
451 if (!g_isInit) {
452 return;
453 }
454 (void)LockHcMutex(g_performDataMutex);
455 if (!g_isPerformDumpEnabled) {
456 UnlockHcMutex(g_performDataMutex);
457 return;
458 }
459 uint32_t index;
460 PerformData **performData;
461 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
462 if ((*performData)->reqId == reqId) {
463 (*performData)->selfIndex = FIRST_START_TIME;
464 (*performData)->status = PERFORM_DATA_STATUS_BEGIN;
465 (*performData)->firstStartTime = HcGetCurTimeInMillis();
466 (*performData)->firstTransmitTime = 0;
467 (*performData)->secondStartTime = 0;
468 (*performData)->secondTransmitTime = 0;
469 (*performData)->thirdStartTime = 0;
470 (*performData)->thirdTransmitTime = 0;
471 (*performData)->fourthStartTime = 0;
472 (*performData)->fourthTransmitTime = 0;
473 (*performData)->onSessionKeyReturnTime = 0;
474 (*performData)->onFinishTime = 0;
475 (*performData)->firstConsumeTime = 0;
476 (*performData)->secondConsumeTime = 0;
477 (*performData)->thirdConsumeTime = 0;
478 (*performData)->fourthConsumeTime = 0;
479 (*performData)->innerConsumeTime = 0;
480 (*performData)->totalConsumeTime = 0;
481 UnlockHcMutex(g_performDataMutex);
482 return;
483 }
484 }
485 UnlockHcMutex(g_performDataMutex);
486 }
487
UpdatePerformDataBySelfIndex(int64_t reqId,int64_t time)488 void UpdatePerformDataBySelfIndex(int64_t reqId, int64_t time)
489 {
490 if (!g_isInit) {
491 return;
492 }
493 (void)LockHcMutex(g_performDataMutex);
494 if (!g_isPerformDumpEnabled) {
495 UnlockHcMutex(g_performDataMutex);
496 return;
497 }
498 uint32_t index;
499 PerformData **performData;
500 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
501 if ((*performData)->reqId == reqId) {
502 UpdateDataBySelfIndex(*performData, time);
503 UnlockHcMutex(g_performDataMutex);
504 return;
505 }
506 }
507 UnlockHcMutex(g_performDataMutex);
508 }
509
UpdatePerformDataByInputIndex(int64_t reqId,PerformTimeIndex timeIndex,int64_t time)510 void UpdatePerformDataByInputIndex(int64_t reqId, PerformTimeIndex timeIndex, int64_t time)
511 {
512 if (!g_isInit) {
513 return;
514 }
515 (void)LockHcMutex(g_performDataMutex);
516 if (!g_isPerformDumpEnabled) {
517 UnlockHcMutex(g_performDataMutex);
518 return;
519 }
520 uint32_t index;
521 PerformData **performData;
522 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
523 if ((*performData)->reqId == reqId) {
524 UpdateDataByInputIndex(*performData, timeIndex, time);
525 UnlockHcMutex(g_performDataMutex);
526 return;
527 }
528 }
529 UnlockHcMutex(g_performDataMutex);
530 }
531
InitPerformanceDumper(void)532 void InitPerformanceDumper(void)
533 {
534 if (g_isInit) {
535 return;
536 }
537 if (g_performDataMutex == NULL) {
538 g_performDataMutex = (HcMutex *)HcMalloc(sizeof(HcMutex), 0);
539 if (g_performDataMutex == NULL) {
540 LOGE("Alloc databaseMutex failed");
541 return;
542 }
543 if (InitHcMutex(g_performDataMutex, false) != HC_SUCCESS) {
544 LOGE("[DB]: Init mutex failed");
545 HcFree(g_performDataMutex);
546 g_performDataMutex = NULL;
547 return;
548 }
549 }
550 (void)LockHcMutex(g_performDataMutex);
551 g_performDataVec = CREATE_HC_VECTOR(PerformDataVec);
552 UnlockHcMutex(g_performDataMutex);
553 DEV_AUTH_REG_PERFORM_DUMP_FUNC(PerformanceDump);
554 g_isInit = true;
555 }
556
DestroyPerformanceDumper(void)557 void DestroyPerformanceDumper(void)
558 {
559 if (!g_isInit) {
560 return;
561 }
562 g_isInit = false;
563 (void)LockHcMutex(g_performDataMutex);
564 g_isPerformDumpEnabled = false;
565 ClearPerformDataVec();
566 DESTROY_HC_VECTOR(PerformDataVec, &g_performDataVec);
567 UnlockHcMutex(g_performDataMutex);
568 DestroyHcMutex(g_performDataMutex);
569 HcFree(g_performDataMutex);
570 g_performDataMutex = NULL;
571 }
572
GetTotalConsumeTimeByReqId(int64_t reqId)573 int64_t GetTotalConsumeTimeByReqId(int64_t reqId)
574 {
575 if (!g_isInit) {
576 return 0;
577 }
578 (void)LockHcMutex(g_performDataMutex);
579 if (!g_isPerformDumpEnabled) {
580 UnlockHcMutex(g_performDataMutex);
581 return 0;
582 }
583 uint32_t index;
584 PerformData **performData;
585 FOR_EACH_HC_VECTOR(g_performDataVec, index, performData) {
586 if ((*performData)->reqId == reqId) {
587 UnlockHcMutex(g_performDataMutex);
588 return (*performData)->onFinishTime - (*performData)->firstStartTime;
589 }
590 }
591 UnlockHcMutex(g_performDataMutex);
592 return 0;
593 }