Line data Source code
1 : /**
2 : * Copyright (c) 2025 Huawei Technologies Co., Ltd.
3 : * This program is free software, you can redistribute it and/or modify it under the terms and conditions of
4 : * CANN Open Software License Agreement Version 2.0 (the "License").
5 : * Please refer to the License for details. You may not use this file except in compliance with the License.
6 : * THIS SOFTWARE IS PROVIDED ON AN "AS IS" BASIS, WITHOUT WARRANTIES OF ANY KIND, EITHER EXPRESS OR IMPLIED,
7 : * INCLUDING BUT NOT LIMITED TO NON-INFRINGEMENT, MERCHANTABILITY, OR FITNESS FOR A PARTICULAR PURPOSE.
8 : * See LICENSE in the root of the software repository for the full text of the License.
9 : */
10 :
11 : #include "profile_manager.h"
12 :
13 : #include <ctime>
14 : #include "bqs_util.h"
15 : #include "bind_cpu_utils.h"
16 : #include "queue_schedule_feature_ctrl.h"
17 : #ifdef USE_PROFILER
18 : #include "hiperf_exception.h"
19 : #include "hiperf_marker.h"
20 : #endif
21 :
22 : namespace bqs {
23 : namespace {
24 : constexpr float64_t SECOND_TO_NANO = 1000000000.0;
25 : constexpr float64_t PROF_THRESHOLD_MS = 0.20;
26 : constexpr float64_t ERROR_LOG_THRESHOLD_MS = 20.0;
27 : const uint32_t MARKER_ENQUEUE_EVENT = 7U;
28 : // event time cost threshold(ms)
29 : const float64_t EVENT_TIME_COST_THRESHOLD_MS = 500.0;
30 : }
31 :
32 8 : ProfileManager::ProfileManager()
33 8 : : enqueEventTrack_({}),
34 8 : frequence_(0.0),
35 8 : profThresholdTick_(0UL),
36 8 : logThresholdTick_(0UL),
37 8 : oneUsForTick_(0.0),
38 8 : profMode_(ProfilingMode::PROFILING_CLOSE),
39 8 : schedInfoTrack_({}),
40 8 : recvReqEventTrack_({}),
41 8 : recvCompEventTrack_({}),
42 8 : sendCompEventTrack_({}),
43 8 : aicpuFeatureUseErrorLogThreshold_(true),
44 8 : recvReqEventCount_(0UL),
45 8 : sendCompEventCount_(0UL),
46 8 : recvCompEventCount_(0UL),
47 8 : enqueueEventCount_(0UL)
48 8 : {}
49 :
50 318 : void ProfileManager::Uninit() const
51 : {
52 : #ifdef USE_PROFILER
53 : ::FiniMarker();
54 : #endif
55 318 : }
56 :
57 1123 : ProfileManager &ProfileManager::GetInstance(const uint32_t resIndex)
58 : {
59 1123 : if (resIndex == 0U) {
60 1109 : static ProfileManager instance;
61 1109 : return instance;
62 : }
63 14 : static ProfileManager instanceExtra;
64 14 : return instanceExtra;
65 : }
66 :
67 18 : void ProfileManager::InitProfileManager(const uint32_t deviceId)
68 : {
69 18 : constexpr float64_t oneMs = 1000000.0; // ns of one ms
70 18 : constexpr float64_t oneUs = 1000.0; // ns of one us
71 18 : frequence_ = static_cast<float64_t>(GetSystemFreq());
72 18 : oneUsForTick_ = oneUs / (SECOND_TO_NANO / frequence_);
73 :
74 18 : const float64_t oneMsForTickTemp = oneMs / (SECOND_TO_NANO / frequence_);
75 18 : const float64_t profThresholdTickTemp = PROF_THRESHOLD_MS * oneMsForTickTemp;
76 18 : profThresholdTick_ = static_cast<uint64_t>(profThresholdTickTemp);
77 :
78 18 : aicpuFeatureUseErrorLogThreshold_ = (bqs::GetRunContext() == bqs::RunContext::HOST) ? false : QSFeatureCtrl::UseErrorLogThreshold(deviceId);
79 18 : const float64_t logThresholdTickTemp = aicpuFeatureUseErrorLogThreshold_ ?
80 : (ERROR_LOG_THRESHOLD_MS * oneMsForTickTemp) : (EVENT_TIME_COST_THRESHOLD_MS * oneMsForTickTemp);
81 18 : logThresholdTick_ = static_cast<uint64_t>(logThresholdTickTemp);
82 18 : BQS_LOG_RUN_INFO("ProfileManager logThresholdTick is [%lu]", logThresholdTick_);
83 :
84 : #ifdef USE_PROFILER
85 : ::InitMarker();
86 : #endif
87 18 : }
88 :
89 3 : void ProfileManager::InitMaker(const uint64_t schedTimes, const uint64_t schedDelay)
90 : {
91 : #ifndef USE_PROFILER
92 3 : enqueEventTrack_.event = 0U;
93 : #else
94 : enqueEventTrack_.event = MARKER_ENQUEUE_EVENT;
95 : #endif
96 3 : enqueEventTrack_.schedTimes = schedTimes;
97 3 : enqueEventTrack_.schedDelay = schedDelay;
98 3 : enqueEventTrack_.state = 0U;
99 3 : enqueEventTrack_.recordThreshold = 0U;
100 3 : enqueEventTrack_.dequeueNum = 0UL;
101 3 : enqueEventTrack_.enqueueNum = 0UL;
102 3 : enqueEventTrack_.fullQueueNum = 0U;
103 3 : enqueEventTrack_.srcQueueNum = 0U;
104 3 : enqueEventTrack_.startStamp = 0UL;
105 3 : enqueEventTrack_.copyCost = 0UL;
106 3 : enqueEventTrack_.relationCost = 0UL;
107 3 : enqueEventTrack_.f2NFCost = 0UL;
108 3 : enqueEventTrack_.totalCost = 0UL;
109 3 : }
110 :
111 57 : void ProfileManager::SetSrcQueueNum(const uint32_t srcQueueNum)
112 : {
113 57 : enqueEventTrack_.srcQueueNum = srcQueueNum;
114 57 : }
115 :
116 30 : void ProfileManager::AddEnqueueNum()
117 : {
118 30 : enqueEventTrack_.enqueueNum++;
119 30 : }
120 :
121 51 : void ProfileManager::AddDequeueNum()
122 : {
123 51 : enqueEventTrack_.dequeueNum++;
124 51 : }
125 :
126 5 : void ProfileManager::AddCopyTotalCost(const uint64_t copyCost)
127 : {
128 5 : enqueEventTrack_.copyCost += copyCost;
129 5 : }
130 :
131 2 : void ProfileManager::SetRelationCost(const uint64_t relationCost)
132 : {
133 2 : enqueEventTrack_.relationCost = relationCost;
134 2 : }
135 :
136 2 : void ProfileManager::Setf2NFCost(const uint64_t f2NFCost)
137 : {
138 2 : enqueEventTrack_.f2NFCost = f2NFCost;
139 2 : }
140 :
141 2 : void ProfileManager::InitMarkerForRecvReqEvent(const uint64_t schedTimes, const uint64_t schedDelay)
142 : {
143 2 : recvReqEventTrack_.schedTimes = schedTimes;
144 2 : recvReqEventTrack_.schedDelay = schedDelay;
145 2 : recvReqEventTrack_.hcclImprobeNum = 0UL;
146 2 : recvReqEventTrack_.totalHcclImprobeCost = 0UL;
147 2 : recvReqEventTrack_.maxHcclImprobeCost = 0UL;
148 2 : recvReqEventTrack_.hcclGetCountNum = 0UL;
149 2 : recvReqEventTrack_.totalHcclGetCountCost = 0UL;
150 2 : recvReqEventTrack_.maxHcclGetCountCost = 0UL;
151 2 : recvReqEventTrack_.hcclImrecvNum = 0UL;
152 2 : recvReqEventTrack_.totalHcclImrecvCost = 0UL;
153 2 : recvReqEventTrack_.maxHcclImrecvCost = 0UL;
154 2 : recvReqEventTrack_.mbufAllocNum = 0UL;
155 2 : recvReqEventTrack_.totalMbufAllocCost = 0UL;
156 2 : recvReqEventTrack_.maxMbufAllocCost = 0UL;
157 2 : }
158 :
159 5 : void ProfileManager::InitMarkerForRecvCompEvent(const uint64_t schedTimes, const uint64_t schedDelay)
160 : {
161 5 : recvCompEventTrack_.schedTimes = schedTimes;
162 5 : recvCompEventTrack_.schedDelay = schedDelay;
163 5 : recvCompEventTrack_.hcclTestSomeNum = 0UL;
164 5 : recvCompEventTrack_.totalHcclTestSomeCost = 0UL;
165 5 : recvCompEventTrack_.maxHcclTestSomeCost = 0UL;
166 5 : recvCompEventTrack_.enqueueNum = 0UL;
167 5 : recvCompEventTrack_.totalEnqueueCost = 0UL;
168 5 : recvCompEventTrack_.maxEnqueueCost = 0UL;
169 5 : recvCompEventTrack_.reqProcCompNum = 0UL;
170 5 : recvCompEventTrack_.totalReqProcCompCost = 0UL;
171 5 : recvCompEventTrack_.maxReqProcCompCost = 0UL;
172 5 : }
173 :
174 3 : void ProfileManager::InitMarkerForSendCompEvent(const uint64_t schedTimes, const uint64_t schedDelay)
175 : {
176 3 : sendCompEventTrack_.schedTimes = schedTimes;
177 3 : sendCompEventTrack_.schedDelay = schedDelay;
178 3 : sendCompEventTrack_.hcclTestSomeNum = 0UL;
179 3 : sendCompEventTrack_.totalHcclTestSomeCost = 0UL;
180 3 : sendCompEventTrack_.maxHcclTestSomeCost = 0UL;
181 3 : sendCompEventTrack_.reqProcCompNum = 0UL;
182 3 : sendCompEventTrack_.totalReqProcCompCost = 0UL;
183 3 : sendCompEventTrack_.maxReqProcCompCost = 0UL;
184 3 : sendCompEventTrack_.mbufFreeNum = 0UL;
185 3 : sendCompEventTrack_.totalMbufFreeCost = 0UL;
186 3 : sendCompEventTrack_.maxMbufFreeCost = 0UL;
187 3 : }
188 :
189 13 : void ProfileManager::AddHcclImprobeCost(const uint64_t cost)
190 : {
191 13 : recvReqEventTrack_.hcclImprobeNum++;
192 13 : recvReqEventTrack_.totalHcclImprobeCost += cost;
193 13 : recvReqEventTrack_.maxHcclImprobeCost = (recvReqEventTrack_.maxHcclImprobeCost > cost) ?
194 10 : recvReqEventTrack_.maxHcclImprobeCost : cost;
195 13 : }
196 :
197 10 : void ProfileManager::AddHcclGetCountCost(const uint64_t cost)
198 : {
199 10 : recvReqEventTrack_.hcclGetCountNum++;
200 10 : recvReqEventTrack_.totalHcclGetCountCost += cost;
201 10 : recvReqEventTrack_.maxHcclGetCountCost = (recvReqEventTrack_.maxHcclGetCountCost > cost) ?
202 8 : recvReqEventTrack_.maxHcclGetCountCost : cost;
203 10 : }
204 :
205 20 : void ProfileManager::AddHcclImrecvCost(const uint64_t cost)
206 : {
207 20 : recvReqEventTrack_.hcclImrecvNum++;
208 20 : recvReqEventTrack_.totalHcclImrecvCost += cost;
209 20 : recvReqEventTrack_.maxHcclImrecvCost = (recvReqEventTrack_.maxHcclImrecvCost > cost) ?
210 16 : recvReqEventTrack_.maxHcclImrecvCost : cost;
211 :
212 20 : schedInfoTrack_.hcclImrecvNum++;
213 20 : schedInfoTrack_.totalHcclImrecvCost += cost;
214 20 : schedInfoTrack_.maxHcclImrecvCost = (schedInfoTrack_.maxHcclImrecvCost > cost) ?
215 16 : schedInfoTrack_.maxHcclImrecvCost : cost;
216 20 : }
217 :
218 13 : void ProfileManager::AddHcclTestSomeCost(const uint64_t cost, const bool isRecvCompEvent)
219 : {
220 13 : if (isRecvCompEvent) {
221 6 : recvCompEventTrack_.hcclTestSomeNum++;
222 6 : recvCompEventTrack_.totalHcclTestSomeCost += cost;
223 8 : recvCompEventTrack_.maxHcclTestSomeCost = (recvCompEventTrack_.maxHcclTestSomeCost > cost) ?
224 2 : recvCompEventTrack_.maxHcclTestSomeCost : cost;
225 : } else {
226 7 : sendCompEventTrack_.hcclTestSomeNum++;
227 7 : sendCompEventTrack_.totalHcclTestSomeCost += cost;
228 11 : sendCompEventTrack_.maxHcclTestSomeCost = (sendCompEventTrack_.maxHcclTestSomeCost > cost) ?
229 4 : sendCompEventTrack_.maxHcclTestSomeCost : cost;
230 : }
231 13 : }
232 :
233 13 : const float64_t ProfileManager::AddReqProcCompCost(const uint64_t cost, const bool isRecvCompEvent)
234 : {
235 13 : if (isRecvCompEvent) {
236 7 : recvCompEventTrack_.reqProcCompNum++;
237 7 : recvCompEventTrack_.totalReqProcCompCost += cost;
238 10 : recvCompEventTrack_.maxReqProcCompCost = (recvCompEventTrack_.maxReqProcCompCost > cost) ?
239 3 : recvCompEventTrack_.maxReqProcCompCost : cost;
240 : } else {
241 6 : sendCompEventTrack_.reqProcCompNum++;
242 6 : sendCompEventTrack_.totalReqProcCompCost += cost;
243 10 : sendCompEventTrack_.maxReqProcCompCost = (sendCompEventTrack_.maxReqProcCompCost > cost) ?
244 4 : sendCompEventTrack_.maxReqProcCompCost : cost;
245 : }
246 13 : return (static_cast<float64_t>(cost) / oneUsForTick_);
247 : }
248 :
249 43 : void ProfileManager::AddHcclIsendCost(const uint64_t cost)
250 : {
251 43 : schedInfoTrack_.hcclIsendNum++;
252 43 : schedInfoTrack_.totalHcclIsendCost += cost;
253 43 : schedInfoTrack_.maxHcclIsendCost = (schedInfoTrack_.maxHcclIsendCost > cost) ?
254 40 : schedInfoTrack_.maxHcclIsendCost : cost;
255 43 : }
256 :
257 13 : void ProfileManager::AddMbufAllocCost(const uint64_t cost)
258 : {
259 13 : recvReqEventTrack_.mbufAllocNum++;
260 13 : recvReqEventTrack_.totalMbufAllocCost += cost;
261 13 : recvReqEventTrack_.maxMbufAllocCost = (recvReqEventTrack_.maxMbufAllocCost > cost) ?
262 8 : recvReqEventTrack_.maxMbufAllocCost : cost;
263 13 : }
264 :
265 3 : void ProfileManager::AddHcclEnqueueCost(const uint64_t cost)
266 : {
267 3 : recvCompEventTrack_.enqueueNum++;
268 3 : recvCompEventTrack_.totalEnqueueCost += cost;
269 3 : recvCompEventTrack_.maxEnqueueCost = (recvCompEventTrack_.maxEnqueueCost > cost) ?
270 0 : recvCompEventTrack_.maxEnqueueCost : cost;
271 3 : }
272 :
273 5 : void ProfileManager::AddMbufFreeCost(const uint64_t cost)
274 : {
275 5 : sendCompEventTrack_.mbufFreeNum++;
276 5 : sendCompEventTrack_.totalMbufFreeCost += cost;
277 5 : sendCompEventTrack_.maxMbufFreeCost = (sendCompEventTrack_.maxMbufFreeCost > cost) ?
278 0 : sendCompEventTrack_.maxMbufFreeCost : cost;
279 5 : }
280 :
281 3 : void ProfileManager::DoMarkerForRecvReqEvent(const uint64_t startTick)
282 : {
283 : // print profiling data
284 3 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
285 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
286 1 : schedInfoTrack_.recvReqEventTotalDelay += recvReqEventTrack_.schedDelay;
287 1 : if (recvReqEventTrack_.schedDelay > schedInfoTrack_.recvReqEventMaxDelay) {
288 0 : schedInfoTrack_.recvReqEventMaxDelay = recvReqEventTrack_.schedDelay;
289 : }
290 1 : if ((recvReqEventTrack_.schedDelay < schedInfoTrack_.recvReqEventMinDelay) || (recvReqEventCount_ == 0U)) {
291 1 : schedInfoTrack_.recvReqEventMinDelay = recvReqEventTrack_.schedDelay;
292 : }
293 1 : recvReqEventCount_++;
294 1 : const uint64_t count = recvReqEventCount_.load();
295 :
296 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
297 :
298 : // calculate average cost for HcclImprobe
299 1 : const float64_t totalHcclImprobeCost =
300 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclImprobeCost) / oneUsForTick_;
301 1 : const uint64_t hcclImprobeNum = recvReqEventTrack_.hcclImprobeNum;
302 1 : const float64_t avgHcclImprobeCost = (hcclImprobeNum == 0UL) ? 0.0 :
303 1 : (totalHcclImprobeCost / static_cast<float64_t>(hcclImprobeNum));
304 1 : const float64_t maxHcclImprobeCost =
305 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclImprobeCost) / oneUsForTick_;
306 :
307 : // calculate average cost for HcclGetCount
308 1 : const float64_t totalHcclGetCountCost =
309 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclGetCountCost) / oneUsForTick_;
310 1 : const uint64_t hcclGetCountNum = recvReqEventTrack_.hcclGetCountNum;
311 1 : const float64_t avgHcclGetCountCost = (hcclGetCountNum == 0UL) ? 0.0 :
312 0 : (totalHcclGetCountCost / static_cast<float64_t>(hcclGetCountNum));
313 1 : const float64_t maxHcclGetCountCost =
314 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclGetCountCost) / oneUsForTick_;
315 :
316 : // calcuate average cost for HcclImrecv
317 1 : const float64_t totalHcclImrecvCost =
318 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclImrecvCost) / oneUsForTick_;
319 1 : const uint64_t hcclImrecvNum = recvReqEventTrack_.hcclImrecvNum;
320 1 : const float64_t avgHcclImrecvCost = (hcclImrecvNum == 0UL) ? 0.0 :
321 0 : (totalHcclImrecvCost / static_cast<float64_t>(hcclImrecvNum));
322 1 : const float64_t maxHcclImrecvCost =
323 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclImrecvCost) / oneUsForTick_;
324 :
325 : // calcuate average cost for mbuf alloc
326 1 : const float64_t totalMbufAllocCost =
327 1 : static_cast<float64_t>(recvReqEventTrack_.totalMbufAllocCost) / oneUsForTick_;
328 1 : const uint64_t mbufAllocNum = recvReqEventTrack_.mbufAllocNum;
329 1 : const float64_t avgMbufAllocCost = (mbufAllocNum == 0UL) ? 0.0 :
330 0 : (totalMbufAllocCost / static_cast<float64_t>(mbufAllocNum));
331 1 : const float64_t maxMbufAllocCost =
332 1 : static_cast<float64_t>(recvReqEventTrack_.maxMbufAllocCost) / oneUsForTick_;
333 :
334 1 : BQS_LOG_RUN_INFO("Hccl time cost info: {recv request event, count[%lu], "
335 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
336 : "hcclImprobe[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
337 : "hcclGetCount[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
338 : "hcclImrecv[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
339 : "mbufAlloc[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus]}.",
340 : count, recvReqEventTrack_.schedTimes, recvReqEventTrack_.schedDelay, totalCost, startTick,
341 : hcclImprobeNum, totalHcclImprobeCost, avgHcclImprobeCost, maxHcclImprobeCost,
342 : hcclGetCountNum, totalHcclGetCountCost, avgHcclGetCountCost, maxHcclGetCountCost,
343 : hcclImrecvNum, totalHcclImrecvCost, avgHcclImrecvCost, maxHcclImrecvCost,
344 : mbufAllocNum, totalMbufAllocCost, avgMbufAllocCost, maxMbufAllocCost);
345 : }
346 3 : }
347 :
348 6 : void ProfileManager::DoMarkerForRecvCompEvent(const uint64_t startTick)
349 : {
350 : // print profiling data
351 6 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
352 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
353 1 : schedInfoTrack_.recvCompEventTotalDelay += recvCompEventTrack_.schedDelay;
354 1 : if (recvCompEventTrack_.schedDelay > schedInfoTrack_.recvCompEventMaxDelay) {
355 0 : schedInfoTrack_.recvCompEventMaxDelay = recvCompEventTrack_.schedDelay;
356 : }
357 1 : if ((recvCompEventTrack_.schedDelay < schedInfoTrack_.recvCompEventMinDelay) || (recvCompEventCount_ == 0U)) {
358 1 : schedInfoTrack_.recvCompEventMinDelay = recvCompEventTrack_.schedDelay;
359 : }
360 1 : recvCompEventCount_++;
361 1 : const uint64_t count = recvCompEventCount_.load();
362 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
363 : // calculate average cost for HcclTestSome
364 1 : const float64_t totalHcclTestSomeCost =
365 1 : static_cast<float64_t>(recvCompEventTrack_.totalHcclTestSomeCost) / oneUsForTick_;
366 1 : const uint64_t hcclTestSomeNum = recvCompEventTrack_.hcclTestSomeNum;
367 1 : const float64_t avgHcclTestSomeCost = (hcclTestSomeNum == 0UL) ? 0.0 :
368 0 : (totalHcclTestSomeCost / static_cast<float64_t>(hcclTestSomeNum));
369 1 : const float64_t maxHcclTestSomeCost =
370 1 : static_cast<float64_t>(recvCompEventTrack_.maxHcclTestSomeCost) / oneUsForTick_;
371 :
372 : // calcuate average cost for enqueue
373 1 : const float64_t totalEnqueueCost = static_cast<float64_t>(recvCompEventTrack_.totalEnqueueCost) / oneUsForTick_;
374 1 : const uint64_t enqueueNum = recvCompEventTrack_.enqueueNum;
375 1 : const float64_t avgEnqueueCost = (enqueueNum == 0UL) ? 0.0 :
376 0 : (totalEnqueueCost / static_cast<float64_t>(enqueueNum));
377 1 : const float64_t maxEnqueueCost = static_cast<float64_t>(recvCompEventTrack_.maxEnqueueCost) / oneUsForTick_;
378 :
379 : // calculate average cost for request process completed
380 1 : const float64_t totalReqProcCompCost =
381 1 : static_cast<float64_t>(recvCompEventTrack_.totalReqProcCompCost) / oneUsForTick_;
382 1 : const uint64_t reqProcCompNum = recvCompEventTrack_.reqProcCompNum;
383 1 : const float64_t avgReqProcCompCost = (reqProcCompNum == 0UL) ? 0.0 :
384 0 : (totalReqProcCompCost / static_cast<float64_t>(reqProcCompNum));
385 1 : const float64_t maxReqProcCompCost =
386 1 : static_cast<float64_t>(recvCompEventTrack_.maxReqProcCompCost) / oneUsForTick_;
387 :
388 : // calculate average cost for test some success one request
389 1 : const float64_t avgSuccTestSomeOneReqCost = (reqProcCompNum == 0UL) ? 0.0 :
390 0 : (totalHcclTestSomeCost / static_cast<float64_t>(reqProcCompNum));
391 :
392 1 : BQS_LOG_RUN_INFO("Hccl time cost info: {recv completion event, count[%lu], "
393 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
394 : "hcclTestSome[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
395 : "enqueue[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
396 : "reqProcComp[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
397 : "testSomeReq[count:%lu, total:%.2fus, average:%.2fus]}.",
398 : count, recvCompEventTrack_.schedTimes, recvCompEventTrack_.schedDelay, totalCost, startTick,
399 : hcclTestSomeNum, totalHcclTestSomeCost, avgHcclTestSomeCost, maxHcclTestSomeCost,
400 : enqueueNum, totalEnqueueCost, avgEnqueueCost, maxEnqueueCost,
401 : reqProcCompNum, totalReqProcCompCost, avgReqProcCompCost, maxReqProcCompCost,
402 : reqProcCompNum, totalHcclTestSomeCost, avgSuccTestSomeOneReqCost);
403 : }
404 6 : }
405 :
406 4 : void ProfileManager::DoMarkerForSendCompEvent(const uint64_t startTick)
407 : {
408 : // print profiling data
409 4 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
410 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
411 1 : schedInfoTrack_.sendCompEventTotalDelay += sendCompEventTrack_.schedDelay;
412 1 : if (sendCompEventTrack_.schedDelay > schedInfoTrack_.sendCompEventMaxDelay) {
413 0 : schedInfoTrack_.sendCompEventMaxDelay = sendCompEventTrack_.schedDelay;
414 : }
415 1 : if ((sendCompEventTrack_.schedDelay < schedInfoTrack_.sendCompEventMinDelay) || (sendCompEventCount_ == 0U)) {
416 1 : schedInfoTrack_.sendCompEventMinDelay = sendCompEventTrack_.schedDelay;
417 : }
418 1 : sendCompEventCount_++;
419 1 : const uint64_t count = sendCompEventCount_.load();
420 :
421 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
422 : // calculate average cost for HcclTestSome
423 1 : const float64_t totalHcclTestSomeCost =
424 1 : static_cast<float64_t>(sendCompEventTrack_.totalHcclTestSomeCost) / oneUsForTick_;
425 1 : const uint64_t hcclTestSomeNum = sendCompEventTrack_.hcclTestSomeNum;
426 1 : const float64_t avgHcclTestSomeCost = (hcclTestSomeNum == 0UL) ? 0.0 :
427 0 : (totalHcclTestSomeCost / static_cast<float64_t>(hcclTestSomeNum));
428 1 : const float64_t maxHcclTestSomeCost =
429 1 : static_cast<float64_t>(sendCompEventTrack_.maxHcclTestSomeCost) / oneUsForTick_;
430 :
431 : // calcuate average cost for mbufFree
432 1 : const float64_t totalMbufFreeCost =
433 1 : static_cast<float64_t>(sendCompEventTrack_.totalMbufFreeCost) / oneUsForTick_;
434 1 : const uint64_t mbufFreeNum = sendCompEventTrack_.mbufFreeNum;
435 1 : const float64_t avgMbufFreeCost = (mbufFreeNum == 0UL) ? 0.0 :
436 0 : (totalMbufFreeCost / static_cast<float64_t>(mbufFreeNum));
437 1 : const float64_t maxMbufFreeCost = static_cast<float64_t>(sendCompEventTrack_.maxMbufFreeCost) / oneUsForTick_;
438 :
439 : // calculate average for request process completed cost
440 1 : const float64_t totalReqProcCompCost =
441 1 : static_cast<float64_t>(sendCompEventTrack_.totalReqProcCompCost) / oneUsForTick_;
442 1 : const uint64_t reqProcCompNum = sendCompEventTrack_.reqProcCompNum;
443 1 : const float64_t avgReqProcCompCost = (reqProcCompNum == 0UL) ? 0.0 :
444 0 : (totalReqProcCompCost / static_cast<float64_t>(reqProcCompNum));
445 1 : const float64_t maxReqProcCompCost =
446 1 : static_cast<float64_t>(sendCompEventTrack_.maxReqProcCompCost) / oneUsForTick_;
447 :
448 : // calculate average cost for test some success one request
449 1 : const float64_t avgSuccTestSomeOneReqCost = (reqProcCompNum == 0UL) ? 0.0 :
450 0 : (totalHcclTestSomeCost / static_cast<float64_t>(reqProcCompNum));
451 :
452 1 : BQS_LOG_RUN_INFO("Hccl time cost info: {send completion event, count[%lu], "
453 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
454 : "hcclTestSome[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
455 : "mbufFree[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
456 : "reqProcComp[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
457 : "testSomeReq[count:%lu, total:%.2fus, average:%.2fus]}.",
458 : count, sendCompEventTrack_.schedTimes, sendCompEventTrack_.schedDelay, totalCost, startTick,
459 : hcclTestSomeNum, totalHcclTestSomeCost, avgHcclTestSomeCost, maxHcclTestSomeCost,
460 : mbufFreeNum, totalMbufFreeCost, avgMbufFreeCost, maxMbufFreeCost,
461 : reqProcCompNum, totalReqProcCompCost, avgReqProcCompCost, maxReqProcCompCost,
462 : reqProcCompNum, totalHcclTestSomeCost, avgSuccTestSomeOneReqCost);
463 : }
464 4 : }
465 :
466 3 : void ProfileManager::TryMarker(const uint64_t startTick)
467 : {
468 3 : const uint64_t totalCost = GetCpuTick() - startTick;
469 : // profile_end value:1
470 3 : enqueEventTrack_.state = 1U;
471 3 : enqueEventTrack_.totalCost = totalCost;
472 3 : enqueEventTrack_.startStamp = startTick;
473 3 : DoMarker();
474 3 : if ((enqueEventTrack_.totalCost > logThresholdTick_) || (enqueEventTrack_.schedDelay > logThresholdTick_)) {
475 2 : DoErrorLog();
476 : }
477 3 : }
478 :
479 3 : void ProfileManager::DoMarker()
480 : {
481 : #ifndef USE_PROFILER
482 3 : BQS_LOG_INFO("Time cost info: {event:%u, state:%u, schedTimes:%lu, schedDelay:%lu ticks, "
483 : "startStamp:%lu, dequeueNum:%lu, enqueueNum:%lu, "
484 : "copyCost:%lu ticks, fullQueueNum:%u, srcQueueNum:%u, "
485 : "relationCost:%lu ticks, f2NFCost:%lu ticks, totalCost:%lu ticks}.",
486 : enqueEventTrack_.event, enqueEventTrack_.state, enqueEventTrack_.schedTimes, enqueEventTrack_.schedDelay,
487 : enqueEventTrack_.startStamp, enqueEventTrack_.dequeueNum, enqueEventTrack_.enqueueNum,
488 : enqueEventTrack_.copyCost, enqueEventTrack_.fullQueueNum, enqueEventTrack_.srcQueueNum,
489 : enqueEventTrack_.relationCost, enqueEventTrack_.f2NFCost, enqueEventTrack_.totalCost);
490 :
491 3 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
492 2 : enqueueEventCount_++;
493 2 : uint64_t count = enqueueEventCount_.load();
494 2 : const float64_t totalHcclIsendCost =
495 2 : static_cast<float64_t>(schedInfoTrack_.totalHcclIsendCost) / oneUsForTick_;
496 2 : const uint64_t hcclIsendNum = schedInfoTrack_.hcclIsendNum;
497 2 : const float64_t avgHcclIsendCost = (hcclIsendNum == 0U) ?
498 0 : 0.0 : totalHcclIsendCost / static_cast<float64_t>(hcclIsendNum);
499 2 : const float64_t maxHcclIsendCost =
500 2 : static_cast<float64_t>(schedInfoTrack_.maxHcclIsendCost) / oneUsForTick_;
501 :
502 2 : const float64_t totalHcclImrecvCost =
503 2 : static_cast<float64_t>(schedInfoTrack_.totalHcclImrecvCost) / oneUsForTick_;
504 2 : const uint64_t hcclImrecvNum = schedInfoTrack_.hcclImrecvNum;
505 2 : const float64_t avgHcclImrecvCost = (hcclImrecvNum == 0U) ?
506 0 : 0.0 : totalHcclImrecvCost / static_cast<float64_t>(hcclImrecvNum);
507 2 : const float64_t maxHcclImrecvCost =
508 2 : static_cast<float64_t>(schedInfoTrack_.maxHcclImrecvCost) / oneUsForTick_;
509 :
510 2 : const auto maxRecvReqEventDelay = static_cast<float64_t>(schedInfoTrack_.recvReqEventMaxDelay) / oneUsForTick_;
511 2 : const auto minRecvReqEventDelay = static_cast<float64_t>(schedInfoTrack_.recvReqEventMinDelay) / oneUsForTick_;
512 2 : const float64_t avgRecvReqEventDelay = (recvReqEventCount_ == 0U) ? 0.0 :
513 0 : static_cast<float64_t>(schedInfoTrack_.recvReqEventTotalDelay) / recvReqEventCount_ / oneUsForTick_;
514 :
515 2 : const auto maxRecvCompEventDelay =
516 2 : static_cast<float64_t>(schedInfoTrack_.recvCompEventMaxDelay) / oneUsForTick_;
517 2 : const auto minRecvCompEventDelay =
518 2 : static_cast<float64_t>(schedInfoTrack_.recvCompEventMinDelay) / oneUsForTick_;
519 2 : const float64_t avgRecvCompEventDelay = (recvCompEventCount_ == 0U) ? 0.0 :
520 0 : static_cast<float64_t>(schedInfoTrack_.recvCompEventTotalDelay) / recvCompEventCount_ / oneUsForTick_;
521 :
522 2 : const auto maxSendCompEventDelay =
523 2 : static_cast<float64_t>(schedInfoTrack_.sendCompEventMaxDelay) / oneUsForTick_;
524 2 : const auto minSendCompEventDelay =
525 2 : static_cast<float64_t>(schedInfoTrack_.sendCompEventMinDelay) / oneUsForTick_;
526 2 : const float64_t avgSendCompEventDelay = (sendCompEventCount_ == 0U) ? 0.0 :
527 0 : static_cast<float64_t>(schedInfoTrack_.sendCompEventTotalDelay) / sendCompEventCount_ / oneUsForTick_;
528 :
529 2 : BQS_LOG_RUN_INFO("Hccl time cost info: {schedTimes[%lu], "
530 : "hcclIsend[HcomSendInfNum:%lu, HcomSendInfCost:%.2fus, average:%.2fus, max:%.2fus]}, "
531 : "HcclImrecv[HcomRecvInfNum:%lu, HcomRecvInfCost:%.2fus, average:%.2fus, max:%.2fus]}, "
532 : "recvReqEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus], "
533 : "recvCompEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus], "
534 : "sendCompEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus].",
535 : count, hcclIsendNum, totalHcclIsendCost, avgHcclIsendCost, maxHcclIsendCost,
536 : hcclImrecvNum, totalHcclImrecvCost, avgHcclImrecvCost, maxHcclImrecvCost,
537 : maxRecvReqEventDelay, avgRecvReqEventDelay, minRecvReqEventDelay,
538 : maxRecvCompEventDelay, avgRecvCompEventDelay, minRecvCompEventDelay,
539 : maxSendCompEventDelay, avgSendCompEventDelay, minSendCompEventDelay);
540 : }
541 : #else
542 : (void)Hiva::MarkerQueueSchedule(enqueEventTrack_);
543 : #endif
544 3 : }
545 :
546 2 : void ProfileManager::DoErrorLog() const
547 : {
548 2 : BQS_LOG_RUN_INFO("DoErrorLog:Time out info:{event:%u, state:%u, schedTimes:%lu, schedDelay:%lu ticks, "
549 : "startStamp:%lu, dequeueNum:%lu, enqueueNum:%lu, "
550 : "copyCost:%lu ticks, fullQueueNum:%u, srcQueueNum:%u, "
551 : "relationCost:%lu ticks, f2NFCost:%lu ticks, totalCost:%lu ticks}",
552 : enqueEventTrack_.event, enqueEventTrack_.state, enqueEventTrack_.schedTimes, enqueEventTrack_.schedDelay,
553 : enqueEventTrack_.startStamp, enqueEventTrack_.dequeueNum, enqueEventTrack_.enqueueNum,
554 : enqueEventTrack_.copyCost, enqueEventTrack_.fullQueueNum, enqueEventTrack_.srcQueueNum,
555 : enqueEventTrack_.relationCost, enqueEventTrack_.f2NFCost, enqueEventTrack_.totalCost);
556 2 : }
557 :
558 7 : BqsStatus ProfileManager::UpdateProfilingMode(const ProfilingMode mode)
559 : {
560 7 : profMode_ = mode;
561 7 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
562 4 : ResetProfiling();
563 : }
564 7 : BQS_LOG_RUN_INFO("Success to update profiling mode:[%u].", static_cast<uint32_t>(mode));
565 7 : return BqsStatus::BQS_STATUS_OK;
566 : }
567 :
568 3 : ProfilingMode ProfileManager::GetProfilingMode() const
569 : {
570 3 : return profMode_;
571 : }
572 :
573 10 : void ProfileManager::ResetProfiling()
574 : {
575 10 : recvReqEventCount_.store(0UL);
576 10 : sendCompEventCount_.store(0UL);
577 10 : recvCompEventCount_.store(0UL);
578 10 : enqueueEventCount_.store(0UL);
579 10 : schedInfoTrack_.hcclIsendNum = 0UL;
580 10 : schedInfoTrack_.totalHcclIsendCost = 0UL;
581 10 : schedInfoTrack_.maxHcclIsendCost = 0UL;
582 10 : schedInfoTrack_.hcclImrecvNum = 0UL;
583 10 : schedInfoTrack_.totalHcclImrecvCost = 0UL;
584 10 : schedInfoTrack_.maxHcclImrecvCost = 0UL;
585 10 : schedInfoTrack_.recvReqEventTotalDelay = 0U;
586 10 : schedInfoTrack_.recvReqEventMaxDelay = 0U;
587 10 : schedInfoTrack_.recvReqEventMinDelay = 0U;
588 10 : schedInfoTrack_.recvCompEventTotalDelay = 0U;
589 10 : schedInfoTrack_.recvCompEventMaxDelay = 0U;
590 10 : schedInfoTrack_.recvCompEventMinDelay = 0U;
591 10 : schedInfoTrack_.sendCompEventTotalDelay = 0U;
592 10 : schedInfoTrack_.sendCompEventMaxDelay = 0U;
593 10 : schedInfoTrack_.sendCompEventMinDelay = 0U;
594 10 : }
595 : } // namespace bqs
|
