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