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