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 : } // namespace
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_ =
79 18 : (bqs::GetRunContext() == bqs::RunContext::HOST) ? false : QSFeatureCtrl::UseErrorLogThreshold(deviceId);
80 18 : const float64_t logThresholdTickTemp = aicpuFeatureUseErrorLogThreshold_ ?
81 : (ERROR_LOG_THRESHOLD_MS * oneMsForTickTemp) :
82 : (EVENT_TIME_COST_THRESHOLD_MS * oneMsForTickTemp);
83 18 : logThresholdTick_ = static_cast<uint64_t>(logThresholdTickTemp);
84 18 : BQS_LOG_RUN_INFO("ProfileManager logThresholdTick is [%lu]", logThresholdTick_);
85 :
86 : #ifdef USE_PROFILER
87 : ::InitMarker();
88 : #endif
89 18 : }
90 :
91 3 : void ProfileManager::InitMaker(const uint64_t schedTimes, const uint64_t schedDelay)
92 : {
93 : #ifndef USE_PROFILER
94 3 : enqueEventTrack_.event = 0U;
95 : #else
96 : enqueEventTrack_.event = MARKER_ENQUEUE_EVENT;
97 : #endif
98 3 : enqueEventTrack_.schedTimes = schedTimes;
99 3 : enqueEventTrack_.schedDelay = schedDelay;
100 3 : enqueEventTrack_.state = 0U;
101 3 : enqueEventTrack_.recordThreshold = 0U;
102 3 : enqueEventTrack_.dequeueNum = 0UL;
103 3 : enqueEventTrack_.enqueueNum = 0UL;
104 3 : enqueEventTrack_.fullQueueNum = 0U;
105 3 : enqueEventTrack_.srcQueueNum = 0U;
106 3 : enqueEventTrack_.startStamp = 0UL;
107 3 : enqueEventTrack_.copyCost = 0UL;
108 3 : enqueEventTrack_.relationCost = 0UL;
109 3 : enqueEventTrack_.f2NFCost = 0UL;
110 3 : enqueEventTrack_.totalCost = 0UL;
111 3 : }
112 :
113 57 : void ProfileManager::SetSrcQueueNum(const uint32_t srcQueueNum) { enqueEventTrack_.srcQueueNum = srcQueueNum; }
114 :
115 30 : void ProfileManager::AddEnqueueNum() { enqueEventTrack_.enqueueNum++; }
116 :
117 51 : void ProfileManager::AddDequeueNum() { enqueEventTrack_.dequeueNum++; }
118 :
119 5 : void ProfileManager::AddCopyTotalCost(const uint64_t copyCost) { enqueEventTrack_.copyCost += copyCost; }
120 :
121 2 : void ProfileManager::SetRelationCost(const uint64_t relationCost) { enqueEventTrack_.relationCost = relationCost; }
122 :
123 2 : void ProfileManager::Setf2NFCost(const uint64_t f2NFCost) { enqueEventTrack_.f2NFCost = f2NFCost; }
124 :
125 2 : void ProfileManager::InitMarkerForRecvReqEvent(const uint64_t schedTimes, const uint64_t schedDelay)
126 : {
127 2 : recvReqEventTrack_.schedTimes = schedTimes;
128 2 : recvReqEventTrack_.schedDelay = schedDelay;
129 2 : recvReqEventTrack_.hcclImprobeNum = 0UL;
130 2 : recvReqEventTrack_.totalHcclImprobeCost = 0UL;
131 2 : recvReqEventTrack_.maxHcclImprobeCost = 0UL;
132 2 : recvReqEventTrack_.hcclGetCountNum = 0UL;
133 2 : recvReqEventTrack_.totalHcclGetCountCost = 0UL;
134 2 : recvReqEventTrack_.maxHcclGetCountCost = 0UL;
135 2 : recvReqEventTrack_.hcclImrecvNum = 0UL;
136 2 : recvReqEventTrack_.totalHcclImrecvCost = 0UL;
137 2 : recvReqEventTrack_.maxHcclImrecvCost = 0UL;
138 2 : recvReqEventTrack_.mbufAllocNum = 0UL;
139 2 : recvReqEventTrack_.totalMbufAllocCost = 0UL;
140 2 : recvReqEventTrack_.maxMbufAllocCost = 0UL;
141 2 : }
142 :
143 5 : void ProfileManager::InitMarkerForRecvCompEvent(const uint64_t schedTimes, const uint64_t schedDelay)
144 : {
145 5 : recvCompEventTrack_.schedTimes = schedTimes;
146 5 : recvCompEventTrack_.schedDelay = schedDelay;
147 5 : recvCompEventTrack_.hcclTestSomeNum = 0UL;
148 5 : recvCompEventTrack_.totalHcclTestSomeCost = 0UL;
149 5 : recvCompEventTrack_.maxHcclTestSomeCost = 0UL;
150 5 : recvCompEventTrack_.enqueueNum = 0UL;
151 5 : recvCompEventTrack_.totalEnqueueCost = 0UL;
152 5 : recvCompEventTrack_.maxEnqueueCost = 0UL;
153 5 : recvCompEventTrack_.reqProcCompNum = 0UL;
154 5 : recvCompEventTrack_.totalReqProcCompCost = 0UL;
155 5 : recvCompEventTrack_.maxReqProcCompCost = 0UL;
156 5 : }
157 :
158 3 : void ProfileManager::InitMarkerForSendCompEvent(const uint64_t schedTimes, const uint64_t schedDelay)
159 : {
160 3 : sendCompEventTrack_.schedTimes = schedTimes;
161 3 : sendCompEventTrack_.schedDelay = schedDelay;
162 3 : sendCompEventTrack_.hcclTestSomeNum = 0UL;
163 3 : sendCompEventTrack_.totalHcclTestSomeCost = 0UL;
164 3 : sendCompEventTrack_.maxHcclTestSomeCost = 0UL;
165 3 : sendCompEventTrack_.reqProcCompNum = 0UL;
166 3 : sendCompEventTrack_.totalReqProcCompCost = 0UL;
167 3 : sendCompEventTrack_.maxReqProcCompCost = 0UL;
168 3 : sendCompEventTrack_.mbufFreeNum = 0UL;
169 3 : sendCompEventTrack_.totalMbufFreeCost = 0UL;
170 3 : sendCompEventTrack_.maxMbufFreeCost = 0UL;
171 3 : }
172 :
173 13 : void ProfileManager::AddHcclImprobeCost(const uint64_t cost)
174 : {
175 13 : recvReqEventTrack_.hcclImprobeNum++;
176 13 : recvReqEventTrack_.totalHcclImprobeCost += cost;
177 13 : recvReqEventTrack_.maxHcclImprobeCost =
178 13 : (recvReqEventTrack_.maxHcclImprobeCost > cost) ? recvReqEventTrack_.maxHcclImprobeCost : cost;
179 13 : }
180 :
181 10 : void ProfileManager::AddHcclGetCountCost(const uint64_t cost)
182 : {
183 10 : recvReqEventTrack_.hcclGetCountNum++;
184 10 : recvReqEventTrack_.totalHcclGetCountCost += cost;
185 10 : recvReqEventTrack_.maxHcclGetCountCost =
186 10 : (recvReqEventTrack_.maxHcclGetCountCost > cost) ? recvReqEventTrack_.maxHcclGetCountCost : cost;
187 10 : }
188 :
189 20 : void ProfileManager::AddHcclImrecvCost(const uint64_t cost)
190 : {
191 20 : recvReqEventTrack_.hcclImrecvNum++;
192 20 : recvReqEventTrack_.totalHcclImrecvCost += cost;
193 20 : recvReqEventTrack_.maxHcclImrecvCost =
194 20 : (recvReqEventTrack_.maxHcclImrecvCost > cost) ? recvReqEventTrack_.maxHcclImrecvCost : cost;
195 :
196 20 : schedInfoTrack_.hcclImrecvNum++;
197 20 : schedInfoTrack_.totalHcclImrecvCost += cost;
198 20 : schedInfoTrack_.maxHcclImrecvCost =
199 20 : (schedInfoTrack_.maxHcclImrecvCost > cost) ? schedInfoTrack_.maxHcclImrecvCost : cost;
200 20 : }
201 :
202 13 : void ProfileManager::AddHcclTestSomeCost(const uint64_t cost, const bool isRecvCompEvent)
203 : {
204 13 : if (isRecvCompEvent) {
205 6 : recvCompEventTrack_.hcclTestSomeNum++;
206 6 : recvCompEventTrack_.totalHcclTestSomeCost += cost;
207 6 : recvCompEventTrack_.maxHcclTestSomeCost =
208 6 : (recvCompEventTrack_.maxHcclTestSomeCost > cost) ? recvCompEventTrack_.maxHcclTestSomeCost : cost;
209 : } else {
210 7 : sendCompEventTrack_.hcclTestSomeNum++;
211 7 : sendCompEventTrack_.totalHcclTestSomeCost += cost;
212 7 : sendCompEventTrack_.maxHcclTestSomeCost =
213 7 : (sendCompEventTrack_.maxHcclTestSomeCost > cost) ? sendCompEventTrack_.maxHcclTestSomeCost : cost;
214 : }
215 13 : }
216 :
217 13 : const float64_t ProfileManager::AddReqProcCompCost(const uint64_t cost, const bool isRecvCompEvent)
218 : {
219 13 : if (isRecvCompEvent) {
220 7 : recvCompEventTrack_.reqProcCompNum++;
221 7 : recvCompEventTrack_.totalReqProcCompCost += cost;
222 7 : recvCompEventTrack_.maxReqProcCompCost =
223 7 : (recvCompEventTrack_.maxReqProcCompCost > cost) ? recvCompEventTrack_.maxReqProcCompCost : cost;
224 : } else {
225 6 : sendCompEventTrack_.reqProcCompNum++;
226 6 : sendCompEventTrack_.totalReqProcCompCost += cost;
227 6 : sendCompEventTrack_.maxReqProcCompCost =
228 6 : (sendCompEventTrack_.maxReqProcCompCost > cost) ? sendCompEventTrack_.maxReqProcCompCost : cost;
229 : }
230 13 : return (static_cast<float64_t>(cost) / oneUsForTick_);
231 : }
232 :
233 43 : void ProfileManager::AddHcclIsendCost(const uint64_t cost)
234 : {
235 43 : schedInfoTrack_.hcclIsendNum++;
236 43 : schedInfoTrack_.totalHcclIsendCost += cost;
237 43 : schedInfoTrack_.maxHcclIsendCost =
238 43 : (schedInfoTrack_.maxHcclIsendCost > cost) ? schedInfoTrack_.maxHcclIsendCost : cost;
239 43 : }
240 :
241 13 : void ProfileManager::AddMbufAllocCost(const uint64_t cost)
242 : {
243 13 : recvReqEventTrack_.mbufAllocNum++;
244 13 : recvReqEventTrack_.totalMbufAllocCost += cost;
245 13 : recvReqEventTrack_.maxMbufAllocCost =
246 13 : (recvReqEventTrack_.maxMbufAllocCost > cost) ? recvReqEventTrack_.maxMbufAllocCost : cost;
247 13 : }
248 :
249 3 : void ProfileManager::AddHcclEnqueueCost(const uint64_t cost)
250 : {
251 3 : recvCompEventTrack_.enqueueNum++;
252 3 : recvCompEventTrack_.totalEnqueueCost += cost;
253 3 : recvCompEventTrack_.maxEnqueueCost =
254 3 : (recvCompEventTrack_.maxEnqueueCost > cost) ? recvCompEventTrack_.maxEnqueueCost : cost;
255 3 : }
256 :
257 5 : void ProfileManager::AddMbufFreeCost(const uint64_t cost)
258 : {
259 5 : sendCompEventTrack_.mbufFreeNum++;
260 5 : sendCompEventTrack_.totalMbufFreeCost += cost;
261 5 : sendCompEventTrack_.maxMbufFreeCost =
262 5 : (sendCompEventTrack_.maxMbufFreeCost > cost) ? sendCompEventTrack_.maxMbufFreeCost : cost;
263 5 : }
264 :
265 3 : void ProfileManager::DoMarkerForRecvReqEvent(const uint64_t startTick)
266 : {
267 : // print profiling data
268 3 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
269 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
270 1 : schedInfoTrack_.recvReqEventTotalDelay += recvReqEventTrack_.schedDelay;
271 1 : if (recvReqEventTrack_.schedDelay > schedInfoTrack_.recvReqEventMaxDelay) {
272 0 : schedInfoTrack_.recvReqEventMaxDelay = recvReqEventTrack_.schedDelay;
273 : }
274 1 : if ((recvReqEventTrack_.schedDelay < schedInfoTrack_.recvReqEventMinDelay) || (recvReqEventCount_ == 0U)) {
275 1 : schedInfoTrack_.recvReqEventMinDelay = recvReqEventTrack_.schedDelay;
276 : }
277 1 : recvReqEventCount_++;
278 1 : const uint64_t count = recvReqEventCount_.load();
279 :
280 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
281 :
282 : // calculate average cost for HcclImprobe
283 1 : const float64_t totalHcclImprobeCost =
284 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclImprobeCost) / oneUsForTick_;
285 1 : const uint64_t hcclImprobeNum = recvReqEventTrack_.hcclImprobeNum;
286 1 : const float64_t avgHcclImprobeCost =
287 1 : (hcclImprobeNum == 0UL) ? 0.0 : (totalHcclImprobeCost / static_cast<float64_t>(hcclImprobeNum));
288 1 : const float64_t maxHcclImprobeCost =
289 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclImprobeCost) / oneUsForTick_;
290 :
291 : // calculate average cost for HcclGetCount
292 1 : const float64_t totalHcclGetCountCost =
293 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclGetCountCost) / oneUsForTick_;
294 1 : const uint64_t hcclGetCountNum = recvReqEventTrack_.hcclGetCountNum;
295 1 : const float64_t avgHcclGetCountCost =
296 1 : (hcclGetCountNum == 0UL) ? 0.0 : (totalHcclGetCountCost / static_cast<float64_t>(hcclGetCountNum));
297 1 : const float64_t maxHcclGetCountCost =
298 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclGetCountCost) / oneUsForTick_;
299 :
300 : // calcuate average cost for HcclImrecv
301 1 : const float64_t totalHcclImrecvCost =
302 1 : static_cast<float64_t>(recvReqEventTrack_.totalHcclImrecvCost) / oneUsForTick_;
303 1 : const uint64_t hcclImrecvNum = recvReqEventTrack_.hcclImrecvNum;
304 1 : const float64_t avgHcclImrecvCost =
305 1 : (hcclImrecvNum == 0UL) ? 0.0 : (totalHcclImrecvCost / static_cast<float64_t>(hcclImrecvNum));
306 1 : const float64_t maxHcclImrecvCost =
307 1 : static_cast<float64_t>(recvReqEventTrack_.maxHcclImrecvCost) / oneUsForTick_;
308 :
309 : // calcuate average cost for mbuf alloc
310 1 : const float64_t totalMbufAllocCost =
311 1 : static_cast<float64_t>(recvReqEventTrack_.totalMbufAllocCost) / oneUsForTick_;
312 1 : const uint64_t mbufAllocNum = recvReqEventTrack_.mbufAllocNum;
313 1 : const float64_t avgMbufAllocCost =
314 1 : (mbufAllocNum == 0UL) ? 0.0 : (totalMbufAllocCost / static_cast<float64_t>(mbufAllocNum));
315 1 : const float64_t maxMbufAllocCost = static_cast<float64_t>(recvReqEventTrack_.maxMbufAllocCost) / oneUsForTick_;
316 :
317 1 : BQS_LOG_RUN_INFO(
318 : "Hccl time cost info: {recv request event, count[%lu], "
319 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
320 : "hcclImprobe[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
321 : "hcclGetCount[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
322 : "hcclImrecv[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
323 : "mbufAlloc[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus]}.",
324 : count, recvReqEventTrack_.schedTimes, recvReqEventTrack_.schedDelay, totalCost, startTick, hcclImprobeNum,
325 : totalHcclImprobeCost, avgHcclImprobeCost, maxHcclImprobeCost, hcclGetCountNum, totalHcclGetCountCost,
326 : avgHcclGetCountCost, maxHcclGetCountCost, hcclImrecvNum, totalHcclImrecvCost, avgHcclImrecvCost,
327 : maxHcclImrecvCost, mbufAllocNum, totalMbufAllocCost, avgMbufAllocCost, maxMbufAllocCost);
328 : }
329 3 : }
330 :
331 6 : void ProfileManager::DoMarkerForRecvCompEvent(const uint64_t startTick)
332 : {
333 : // print profiling data
334 6 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
335 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
336 1 : schedInfoTrack_.recvCompEventTotalDelay += recvCompEventTrack_.schedDelay;
337 1 : if (recvCompEventTrack_.schedDelay > schedInfoTrack_.recvCompEventMaxDelay) {
338 0 : schedInfoTrack_.recvCompEventMaxDelay = recvCompEventTrack_.schedDelay;
339 : }
340 1 : if ((recvCompEventTrack_.schedDelay < schedInfoTrack_.recvCompEventMinDelay) || (recvCompEventCount_ == 0U)) {
341 1 : schedInfoTrack_.recvCompEventMinDelay = recvCompEventTrack_.schedDelay;
342 : }
343 1 : recvCompEventCount_++;
344 1 : const uint64_t count = recvCompEventCount_.load();
345 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
346 : // calculate average cost for HcclTestSome
347 1 : const float64_t totalHcclTestSomeCost =
348 1 : static_cast<float64_t>(recvCompEventTrack_.totalHcclTestSomeCost) / oneUsForTick_;
349 1 : const uint64_t hcclTestSomeNum = recvCompEventTrack_.hcclTestSomeNum;
350 1 : const float64_t avgHcclTestSomeCost =
351 1 : (hcclTestSomeNum == 0UL) ? 0.0 : (totalHcclTestSomeCost / static_cast<float64_t>(hcclTestSomeNum));
352 1 : const float64_t maxHcclTestSomeCost =
353 1 : static_cast<float64_t>(recvCompEventTrack_.maxHcclTestSomeCost) / oneUsForTick_;
354 :
355 : // calcuate average cost for enqueue
356 1 : const float64_t totalEnqueueCost = static_cast<float64_t>(recvCompEventTrack_.totalEnqueueCost) / oneUsForTick_;
357 1 : const uint64_t enqueueNum = recvCompEventTrack_.enqueueNum;
358 1 : const float64_t avgEnqueueCost =
359 1 : (enqueueNum == 0UL) ? 0.0 : (totalEnqueueCost / static_cast<float64_t>(enqueueNum));
360 1 : const float64_t maxEnqueueCost = static_cast<float64_t>(recvCompEventTrack_.maxEnqueueCost) / oneUsForTick_;
361 :
362 : // calculate average cost for request process completed
363 1 : const float64_t totalReqProcCompCost =
364 1 : static_cast<float64_t>(recvCompEventTrack_.totalReqProcCompCost) / oneUsForTick_;
365 1 : const uint64_t reqProcCompNum = recvCompEventTrack_.reqProcCompNum;
366 1 : const float64_t avgReqProcCompCost =
367 1 : (reqProcCompNum == 0UL) ? 0.0 : (totalReqProcCompCost / static_cast<float64_t>(reqProcCompNum));
368 1 : const float64_t maxReqProcCompCost =
369 1 : static_cast<float64_t>(recvCompEventTrack_.maxReqProcCompCost) / oneUsForTick_;
370 :
371 : // calculate average cost for test some success one request
372 1 : const float64_t avgSuccTestSomeOneReqCost =
373 1 : (reqProcCompNum == 0UL) ? 0.0 : (totalHcclTestSomeCost / static_cast<float64_t>(reqProcCompNum));
374 :
375 1 : BQS_LOG_RUN_INFO(
376 : "Hccl time cost info: {recv completion event, count[%lu], "
377 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
378 : "hcclTestSome[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
379 : "enqueue[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
380 : "reqProcComp[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
381 : "testSomeReq[count:%lu, total:%.2fus, average:%.2fus]}.",
382 : count, recvCompEventTrack_.schedTimes, recvCompEventTrack_.schedDelay, totalCost, startTick,
383 : hcclTestSomeNum, totalHcclTestSomeCost, avgHcclTestSomeCost, maxHcclTestSomeCost, enqueueNum,
384 : totalEnqueueCost, avgEnqueueCost, maxEnqueueCost, reqProcCompNum, totalReqProcCompCost, avgReqProcCompCost,
385 : maxReqProcCompCost, reqProcCompNum, totalHcclTestSomeCost, avgSuccTestSomeOneReqCost);
386 : }
387 6 : }
388 :
389 4 : void ProfileManager::DoMarkerForSendCompEvent(const uint64_t startTick)
390 : {
391 : // print profiling data
392 4 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
393 1 : const uint64_t totalCostTick = GetCpuTick() - startTick;
394 1 : schedInfoTrack_.sendCompEventTotalDelay += sendCompEventTrack_.schedDelay;
395 1 : if (sendCompEventTrack_.schedDelay > schedInfoTrack_.sendCompEventMaxDelay) {
396 0 : schedInfoTrack_.sendCompEventMaxDelay = sendCompEventTrack_.schedDelay;
397 : }
398 1 : if ((sendCompEventTrack_.schedDelay < schedInfoTrack_.sendCompEventMinDelay) || (sendCompEventCount_ == 0U)) {
399 1 : schedInfoTrack_.sendCompEventMinDelay = sendCompEventTrack_.schedDelay;
400 : }
401 1 : sendCompEventCount_++;
402 1 : const uint64_t count = sendCompEventCount_.load();
403 :
404 1 : const float64_t totalCost = static_cast<float64_t>(totalCostTick) / oneUsForTick_;
405 : // calculate average cost for HcclTestSome
406 1 : const float64_t totalHcclTestSomeCost =
407 1 : static_cast<float64_t>(sendCompEventTrack_.totalHcclTestSomeCost) / oneUsForTick_;
408 1 : const uint64_t hcclTestSomeNum = sendCompEventTrack_.hcclTestSomeNum;
409 1 : const float64_t avgHcclTestSomeCost =
410 1 : (hcclTestSomeNum == 0UL) ? 0.0 : (totalHcclTestSomeCost / static_cast<float64_t>(hcclTestSomeNum));
411 1 : const float64_t maxHcclTestSomeCost =
412 1 : static_cast<float64_t>(sendCompEventTrack_.maxHcclTestSomeCost) / oneUsForTick_;
413 :
414 : // calcuate average cost for mbufFree
415 1 : const float64_t totalMbufFreeCost =
416 1 : static_cast<float64_t>(sendCompEventTrack_.totalMbufFreeCost) / oneUsForTick_;
417 1 : const uint64_t mbufFreeNum = sendCompEventTrack_.mbufFreeNum;
418 1 : const float64_t avgMbufFreeCost =
419 1 : (mbufFreeNum == 0UL) ? 0.0 : (totalMbufFreeCost / static_cast<float64_t>(mbufFreeNum));
420 1 : const float64_t maxMbufFreeCost = static_cast<float64_t>(sendCompEventTrack_.maxMbufFreeCost) / oneUsForTick_;
421 :
422 : // calculate average for request process completed cost
423 1 : const float64_t totalReqProcCompCost =
424 1 : static_cast<float64_t>(sendCompEventTrack_.totalReqProcCompCost) / oneUsForTick_;
425 1 : const uint64_t reqProcCompNum = sendCompEventTrack_.reqProcCompNum;
426 1 : const float64_t avgReqProcCompCost =
427 1 : (reqProcCompNum == 0UL) ? 0.0 : (totalReqProcCompCost / static_cast<float64_t>(reqProcCompNum));
428 1 : const float64_t maxReqProcCompCost =
429 1 : static_cast<float64_t>(sendCompEventTrack_.maxReqProcCompCost) / oneUsForTick_;
430 :
431 : // calculate average cost for test some success one request
432 1 : const float64_t avgSuccTestSomeOneReqCost =
433 1 : (reqProcCompNum == 0UL) ? 0.0 : (totalHcclTestSomeCost / static_cast<float64_t>(reqProcCompNum));
434 :
435 1 : BQS_LOG_RUN_INFO(
436 : "Hccl time cost info: {send completion event, count[%lu], "
437 : "schedTimes[%lu], schedDelay[%lu]ticks, totalCost[%.2f]us, startStamp[%lu], "
438 : "hcclTestSome[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
439 : "mbufFree[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
440 : "reqProcComp[count:%lu, total:%.2fus, average:%.2fus, max:%.2fus], "
441 : "testSomeReq[count:%lu, total:%.2fus, average:%.2fus]}.",
442 : count, sendCompEventTrack_.schedTimes, sendCompEventTrack_.schedDelay, totalCost, startTick,
443 : hcclTestSomeNum, totalHcclTestSomeCost, avgHcclTestSomeCost, maxHcclTestSomeCost, mbufFreeNum,
444 : totalMbufFreeCost, avgMbufFreeCost, maxMbufFreeCost, reqProcCompNum, totalReqProcCompCost,
445 : avgReqProcCompCost, maxReqProcCompCost, reqProcCompNum, totalHcclTestSomeCost, avgSuccTestSomeOneReqCost);
446 : }
447 4 : }
448 :
449 3 : void ProfileManager::TryMarker(const uint64_t startTick)
450 : {
451 3 : const uint64_t totalCost = GetCpuTick() - startTick;
452 : // profile_end value:1
453 3 : enqueEventTrack_.state = 1U;
454 3 : enqueEventTrack_.totalCost = totalCost;
455 3 : enqueEventTrack_.startStamp = startTick;
456 3 : DoMarker();
457 3 : if ((enqueEventTrack_.totalCost > logThresholdTick_) || (enqueEventTrack_.schedDelay > logThresholdTick_)) {
458 2 : DoErrorLog();
459 : }
460 3 : }
461 :
462 3 : void ProfileManager::DoMarker()
463 : {
464 : #ifndef USE_PROFILER
465 3 : BQS_LOG_INFO(
466 : "Time cost info: {event:%u, state:%u, schedTimes:%lu, schedDelay:%lu ticks, "
467 : "startStamp:%lu, dequeueNum:%lu, enqueueNum:%lu, "
468 : "copyCost:%lu ticks, fullQueueNum:%u, srcQueueNum:%u, "
469 : "relationCost:%lu ticks, f2NFCost:%lu ticks, totalCost:%lu ticks}.",
470 : enqueEventTrack_.event, enqueEventTrack_.state, enqueEventTrack_.schedTimes, enqueEventTrack_.schedDelay,
471 : enqueEventTrack_.startStamp, enqueEventTrack_.dequeueNum, enqueEventTrack_.enqueueNum,
472 : enqueEventTrack_.copyCost, enqueEventTrack_.fullQueueNum, enqueEventTrack_.srcQueueNum,
473 : enqueEventTrack_.relationCost, enqueEventTrack_.f2NFCost, enqueEventTrack_.totalCost);
474 :
475 3 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
476 2 : enqueueEventCount_++;
477 2 : uint64_t count = enqueueEventCount_.load();
478 2 : const float64_t totalHcclIsendCost = static_cast<float64_t>(schedInfoTrack_.totalHcclIsendCost) / oneUsForTick_;
479 2 : const uint64_t hcclIsendNum = schedInfoTrack_.hcclIsendNum;
480 2 : const float64_t avgHcclIsendCost =
481 2 : (hcclIsendNum == 0U) ? 0.0 : totalHcclIsendCost / static_cast<float64_t>(hcclIsendNum);
482 2 : const float64_t maxHcclIsendCost = static_cast<float64_t>(schedInfoTrack_.maxHcclIsendCost) / oneUsForTick_;
483 :
484 2 : const float64_t totalHcclImrecvCost =
485 2 : static_cast<float64_t>(schedInfoTrack_.totalHcclImrecvCost) / oneUsForTick_;
486 2 : const uint64_t hcclImrecvNum = schedInfoTrack_.hcclImrecvNum;
487 2 : const float64_t avgHcclImrecvCost =
488 2 : (hcclImrecvNum == 0U) ? 0.0 : totalHcclImrecvCost / static_cast<float64_t>(hcclImrecvNum);
489 2 : const float64_t maxHcclImrecvCost = static_cast<float64_t>(schedInfoTrack_.maxHcclImrecvCost) / oneUsForTick_;
490 :
491 2 : const auto maxRecvReqEventDelay = static_cast<float64_t>(schedInfoTrack_.recvReqEventMaxDelay) / oneUsForTick_;
492 2 : const auto minRecvReqEventDelay = static_cast<float64_t>(schedInfoTrack_.recvReqEventMinDelay) / oneUsForTick_;
493 : const float64_t avgRecvReqEventDelay =
494 2 : (recvReqEventCount_ == 0U) ?
495 : 0.0 :
496 0 : static_cast<float64_t>(schedInfoTrack_.recvReqEventTotalDelay) / recvReqEventCount_ / oneUsForTick_;
497 :
498 2 : const auto maxRecvCompEventDelay =
499 2 : static_cast<float64_t>(schedInfoTrack_.recvCompEventMaxDelay) / oneUsForTick_;
500 2 : const auto minRecvCompEventDelay =
501 2 : static_cast<float64_t>(schedInfoTrack_.recvCompEventMinDelay) / oneUsForTick_;
502 : const float64_t avgRecvCompEventDelay =
503 2 : (recvCompEventCount_ == 0U) ?
504 : 0.0 :
505 0 : static_cast<float64_t>(schedInfoTrack_.recvCompEventTotalDelay) / recvCompEventCount_ / oneUsForTick_;
506 :
507 2 : const auto maxSendCompEventDelay =
508 2 : static_cast<float64_t>(schedInfoTrack_.sendCompEventMaxDelay) / oneUsForTick_;
509 2 : const auto minSendCompEventDelay =
510 2 : static_cast<float64_t>(schedInfoTrack_.sendCompEventMinDelay) / oneUsForTick_;
511 : const float64_t avgSendCompEventDelay =
512 2 : (sendCompEventCount_ == 0U) ?
513 : 0.0 :
514 0 : static_cast<float64_t>(schedInfoTrack_.sendCompEventTotalDelay) / sendCompEventCount_ / oneUsForTick_;
515 :
516 2 : BQS_LOG_RUN_INFO(
517 : "Hccl time cost info: {schedTimes[%lu], "
518 : "hcclIsend[HcomSendInfNum:%lu, HcomSendInfCost:%.2fus, average:%.2fus, max:%.2fus]}, "
519 : "HcclImrecv[HcomRecvInfNum:%lu, HcomRecvInfCost:%.2fus, average:%.2fus, max:%.2fus]}, "
520 : "recvReqEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus], "
521 : "recvCompEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus], "
522 : "sendCompEschedDelay[max: %.2fus, average: %.2fus, min: %.2fus].",
523 : count, hcclIsendNum, totalHcclIsendCost, avgHcclIsendCost, maxHcclIsendCost, hcclImrecvNum,
524 : totalHcclImrecvCost, avgHcclImrecvCost, maxHcclImrecvCost, maxRecvReqEventDelay, avgRecvReqEventDelay,
525 : minRecvReqEventDelay, maxRecvCompEventDelay, avgRecvCompEventDelay, minRecvCompEventDelay,
526 : maxSendCompEventDelay, avgSendCompEventDelay, minSendCompEventDelay);
527 : }
528 : #else
529 : (void)Hiva::MarkerQueueSchedule(enqueEventTrack_);
530 : #endif
531 3 : }
532 :
533 2 : void ProfileManager::DoErrorLog() const
534 : {
535 2 : BQS_LOG_RUN_INFO(
536 : "DoErrorLog:Time out info:{event:%u, state:%u, schedTimes:%lu, schedDelay:%lu ticks, "
537 : "startStamp:%lu, dequeueNum:%lu, enqueueNum:%lu, "
538 : "copyCost:%lu ticks, fullQueueNum:%u, srcQueueNum:%u, "
539 : "relationCost:%lu ticks, f2NFCost:%lu ticks, totalCost:%lu ticks}",
540 : enqueEventTrack_.event, enqueEventTrack_.state, enqueEventTrack_.schedTimes, enqueEventTrack_.schedDelay,
541 : enqueEventTrack_.startStamp, enqueEventTrack_.dequeueNum, enqueEventTrack_.enqueueNum,
542 : enqueEventTrack_.copyCost, enqueEventTrack_.fullQueueNum, enqueEventTrack_.srcQueueNum,
543 : enqueEventTrack_.relationCost, enqueEventTrack_.f2NFCost, enqueEventTrack_.totalCost);
544 2 : }
545 :
546 7 : BqsStatus ProfileManager::UpdateProfilingMode(const ProfilingMode mode)
547 : {
548 7 : profMode_ = mode;
549 7 : if (profMode_ == bqs::ProfilingMode::PROFILING_OPEN) {
550 4 : ResetProfiling();
551 : }
552 7 : BQS_LOG_RUN_INFO("Success to update profiling mode:[%u].", static_cast<uint32_t>(mode));
553 7 : return BqsStatus::BQS_STATUS_OK;
554 : }
555 :
556 3 : ProfilingMode ProfileManager::GetProfilingMode() const { return profMode_; }
557 :
558 10 : void ProfileManager::ResetProfiling()
559 : {
560 10 : recvReqEventCount_.store(0UL);
561 10 : sendCompEventCount_.store(0UL);
562 10 : recvCompEventCount_.store(0UL);
563 10 : enqueueEventCount_.store(0UL);
564 10 : schedInfoTrack_.hcclIsendNum = 0UL;
565 10 : schedInfoTrack_.totalHcclIsendCost = 0UL;
566 10 : schedInfoTrack_.maxHcclIsendCost = 0UL;
567 10 : schedInfoTrack_.hcclImrecvNum = 0UL;
568 10 : schedInfoTrack_.totalHcclImrecvCost = 0UL;
569 10 : schedInfoTrack_.maxHcclImrecvCost = 0UL;
570 10 : schedInfoTrack_.recvReqEventTotalDelay = 0U;
571 10 : schedInfoTrack_.recvReqEventMaxDelay = 0U;
572 10 : schedInfoTrack_.recvReqEventMinDelay = 0U;
573 10 : schedInfoTrack_.recvCompEventTotalDelay = 0U;
574 10 : schedInfoTrack_.recvCompEventMaxDelay = 0U;
575 10 : schedInfoTrack_.recvCompEventMinDelay = 0U;
576 10 : schedInfoTrack_.sendCompEventTotalDelay = 0U;
577 10 : schedInfoTrack_.sendCompEventMaxDelay = 0U;
578 10 : schedInfoTrack_.sendCompEventMinDelay = 0U;
579 10 : }
580 : } // namespace bqs
|
