/root/doris/be/src/util/runtime_profile.cpp
Line | Count | Source (jump to first uncovered line) |
1 | | // Licensed to the Apache Software Foundation (ASF) under one |
2 | | // or more contributor license agreements. See the NOTICE file |
3 | | // distributed with this work for additional information |
4 | | // regarding copyright ownership. The ASF licenses this file |
5 | | // to you under the Apache License, Version 2.0 (the |
6 | | // "License"); you may not use this file except in compliance |
7 | | // with the License. You may obtain a copy of the License at |
8 | | // |
9 | | // http://www.apache.org/licenses/LICENSE-2.0 |
10 | | // |
11 | | // Unless required by applicable law or agreed to in writing, |
12 | | // software distributed under the License is distributed on an |
13 | | // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
14 | | // KIND, either express or implied. See the License for the |
15 | | // specific language governing permissions and limitations |
16 | | // under the License. |
17 | | // This file is copied from |
18 | | // https://github.com/apache/impala/blob/branch-2.9.0/be/src/util/runtime-profile.cc |
19 | | // and modified by Doris |
20 | | |
21 | | #include "util/runtime_profile.h" |
22 | | |
23 | | #include <gen_cpp/RuntimeProfile_types.h> |
24 | | #include <rapidjson/encodings.h> |
25 | | #include <rapidjson/stringbuffer.h> |
26 | | #include <rapidjson/writer.h> |
27 | | |
28 | | #include <iomanip> |
29 | | #include <iostream> |
30 | | |
31 | | #include "common/object_pool.h" |
32 | | #include "util/container_util.hpp" |
33 | | |
34 | | namespace doris { |
35 | | |
36 | | // Thread counters name |
37 | | static const std::string THREAD_TOTAL_TIME = "TotalWallClockTime"; |
38 | | static const std::string THREAD_VOLUNTARY_CONTEXT_SWITCHES = "VoluntaryContextSwitches"; |
39 | | static const std::string THREAD_INVOLUNTARY_CONTEXT_SWITCHES = "InvoluntaryContextSwitches"; |
40 | | |
41 | | // The root counter name for all top level counters. |
42 | | static const std::string ROOT_COUNTER; |
43 | | |
44 | | RuntimeProfile::RuntimeProfile(const std::string& name, bool is_averaged_profile) |
45 | | : _pool(new ObjectPool()), |
46 | | _name(name), |
47 | | _metadata(-1), |
48 | | _timestamp(-1), |
49 | | _is_averaged_profile(is_averaged_profile), |
50 | | _counter_total_time(TUnit::TIME_NS, 0, 3), |
51 | 2.17k | _local_time_percent(0) { |
52 | | // TotalTime counter has level3 to disable it from plan profile, because |
53 | | // it contains its child running time, we use exec time instead. |
54 | 2.17k | _counter_map["TotalTime"] = &_counter_total_time; |
55 | 2.17k | } |
56 | | |
57 | 2.16k | RuntimeProfile::~RuntimeProfile() = default; |
58 | | |
59 | 0 | void RuntimeProfile::merge(RuntimeProfile* other) { |
60 | 0 | DCHECK(other != nullptr); |
61 | | |
62 | | // Merge this level |
63 | 0 | { |
64 | 0 | CounterMap::iterator dst_iter; |
65 | 0 | CounterMap::const_iterator src_iter; |
66 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
67 | 0 | std::lock_guard<std::mutex> m(other->_counter_map_lock); |
68 | |
|
69 | 0 | for (src_iter = other->_counter_map.begin(); src_iter != other->_counter_map.end(); |
70 | 0 | ++src_iter) { |
71 | 0 | dst_iter = _counter_map.find(src_iter->first); |
72 | |
|
73 | 0 | if (dst_iter == _counter_map.end()) { |
74 | 0 | _counter_map[src_iter->first] = _pool->add( |
75 | 0 | new Counter(src_iter->second->type(), src_iter->second->value())); |
76 | 0 | } else { |
77 | 0 | DCHECK(dst_iter->second->type() == src_iter->second->type()); |
78 | |
|
79 | 0 | if (dst_iter->second->type() == TUnit::DOUBLE_VALUE) { |
80 | 0 | double new_val = |
81 | 0 | dst_iter->second->double_value() + src_iter->second->double_value(); |
82 | 0 | dst_iter->second->set(new_val); |
83 | 0 | } else { |
84 | 0 | dst_iter->second->update(src_iter->second->value()); |
85 | 0 | } |
86 | 0 | } |
87 | 0 | } |
88 | |
|
89 | 0 | ChildCounterMap::const_iterator child_counter_src_itr; |
90 | |
|
91 | 0 | for (child_counter_src_itr = other->_child_counter_map.begin(); |
92 | 0 | child_counter_src_itr != other->_child_counter_map.end(); ++child_counter_src_itr) { |
93 | 0 | std::set<std::string>* child_counters = find_or_insert( |
94 | 0 | &_child_counter_map, child_counter_src_itr->first, std::set<std::string>()); |
95 | 0 | child_counters->insert(child_counter_src_itr->second.begin(), |
96 | 0 | child_counter_src_itr->second.end()); |
97 | 0 | } |
98 | 0 | } |
99 | |
|
100 | 0 | { |
101 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
102 | 0 | std::lock_guard<std::mutex> m(other->_children_lock); |
103 | | |
104 | | // Recursively merge children with matching names |
105 | 0 | for (int i = 0; i < other->_children.size(); ++i) { |
106 | 0 | RuntimeProfile* other_child = other->_children[i].first; |
107 | 0 | ChildMap::iterator j = _child_map.find(other_child->_name); |
108 | 0 | RuntimeProfile* child = nullptr; |
109 | |
|
110 | 0 | if (j != _child_map.end()) { |
111 | 0 | child = j->second; |
112 | 0 | } else { |
113 | 0 | child = _pool->add(new RuntimeProfile(other_child->_name)); |
114 | 0 | child->_local_time_percent = other_child->_local_time_percent; |
115 | 0 | child->_metadata = other_child->_metadata; |
116 | 0 | child->_timestamp = other_child->_timestamp; |
117 | 0 | bool indent_other_child = other->_children[i].second; |
118 | 0 | _child_map[child->_name] = child; |
119 | 0 | _children.push_back(std::make_pair(child, indent_other_child)); |
120 | 0 | } |
121 | |
|
122 | 0 | child->merge(other_child); |
123 | 0 | } |
124 | 0 | } |
125 | 0 | } |
126 | | |
127 | 0 | void RuntimeProfile::update(const TRuntimeProfileTree& thrift_profile) { |
128 | 0 | int idx = 0; |
129 | 0 | update(thrift_profile.nodes, &idx); |
130 | 0 | DCHECK_EQ(idx, thrift_profile.nodes.size()); |
131 | 0 | } |
132 | | |
133 | 0 | void RuntimeProfile::update(const std::vector<TRuntimeProfileNode>& nodes, int* idx) { |
134 | 0 | DCHECK_LT(*idx, nodes.size()); |
135 | 0 | const TRuntimeProfileNode& node = nodes[*idx]; |
136 | 0 | { |
137 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
138 | | // update this level |
139 | 0 | std::map<std::string, Counter*>::iterator dst_iter; |
140 | |
|
141 | 0 | for (int i = 0; i < node.counters.size(); ++i) { |
142 | 0 | const TCounter& tcounter = node.counters[i]; |
143 | 0 | CounterMap::iterator j = _counter_map.find(tcounter.name); |
144 | |
|
145 | 0 | if (j == _counter_map.end()) { |
146 | 0 | _counter_map[tcounter.name] = |
147 | 0 | _pool->add(new Counter(tcounter.type, tcounter.value)); |
148 | 0 | } else { |
149 | 0 | if (j->second->type() != tcounter.type) { |
150 | 0 | LOG(ERROR) << "Cannot update counters with the same name (" << j->first |
151 | 0 | << ") but different types."; |
152 | 0 | } else { |
153 | 0 | j->second->set(tcounter.value); |
154 | 0 | } |
155 | 0 | } |
156 | 0 | } |
157 | |
|
158 | 0 | ChildCounterMap::const_iterator child_counter_src_itr; |
159 | |
|
160 | 0 | for (child_counter_src_itr = node.child_counters_map.begin(); |
161 | 0 | child_counter_src_itr != node.child_counters_map.end(); ++child_counter_src_itr) { |
162 | 0 | std::set<std::string>* child_counters = find_or_insert( |
163 | 0 | &_child_counter_map, child_counter_src_itr->first, std::set<std::string>()); |
164 | 0 | child_counters->insert(child_counter_src_itr->second.begin(), |
165 | 0 | child_counter_src_itr->second.end()); |
166 | 0 | } |
167 | 0 | } |
168 | |
|
169 | 0 | { |
170 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
171 | 0 | const InfoStrings& info_strings = node.info_strings; |
172 | 0 | for (const std::string& key : node.info_strings_display_order) { |
173 | | // Look for existing info strings and update in place. If there |
174 | | // are new strings, add them to the end of the display order. |
175 | | // TODO: Is nodes.info_strings always a superset of |
176 | | // _info_strings? If so, can just copy the display order. |
177 | 0 | InfoStrings::const_iterator it = info_strings.find(key); |
178 | 0 | DCHECK(it != info_strings.end()); |
179 | 0 | InfoStrings::iterator existing = _info_strings.find(key); |
180 | |
|
181 | 0 | if (existing == _info_strings.end()) { |
182 | 0 | _info_strings.insert(std::make_pair(key, it->second)); |
183 | 0 | _info_strings_display_order.push_back(key); |
184 | 0 | } else { |
185 | 0 | _info_strings[key] = it->second; |
186 | 0 | } |
187 | 0 | } |
188 | 0 | } |
189 | |
|
190 | 0 | ++*idx; |
191 | 0 | { |
192 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
193 | | |
194 | | // update children with matching names; create new ones if they don't match |
195 | 0 | for (int i = 0; i < node.num_children; ++i) { |
196 | 0 | const TRuntimeProfileNode& tchild = nodes[*idx]; |
197 | 0 | ChildMap::iterator j = _child_map.find(tchild.name); |
198 | 0 | RuntimeProfile* child = nullptr; |
199 | |
|
200 | 0 | if (j != _child_map.end()) { |
201 | 0 | child = j->second; |
202 | 0 | } else { |
203 | 0 | child = _pool->add(new RuntimeProfile(tchild.name)); |
204 | 0 | child->_metadata = tchild.metadata; |
205 | 0 | child->_timestamp = tchild.timestamp; |
206 | 0 | _child_map[tchild.name] = child; |
207 | 0 | _children.push_back(std::make_pair(child, tchild.indent)); |
208 | 0 | } |
209 | |
|
210 | 0 | child->update(nodes, idx); |
211 | 0 | } |
212 | 0 | } |
213 | 0 | } |
214 | | |
215 | 0 | void RuntimeProfile::divide(int n) { |
216 | 0 | DCHECK_GT(n, 0); |
217 | 0 | std::map<std::string, Counter*>::iterator iter; |
218 | 0 | { |
219 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
220 | |
|
221 | 0 | for (iter = _counter_map.begin(); iter != _counter_map.end(); ++iter) { |
222 | 0 | if (iter->second->type() == TUnit::DOUBLE_VALUE) { |
223 | 0 | iter->second->set(iter->second->double_value() / n); |
224 | 0 | } else { |
225 | 0 | int64_t value = iter->second->_value.load(); |
226 | 0 | value = value / n; |
227 | 0 | iter->second->_value.store(value); |
228 | 0 | } |
229 | 0 | } |
230 | 0 | } |
231 | 0 | { |
232 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
233 | |
|
234 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
235 | 0 | i->second->divide(n); |
236 | 0 | } |
237 | 0 | } |
238 | 0 | } |
239 | | |
240 | 0 | void RuntimeProfile::clear_children() { |
241 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
242 | 0 | _children.clear(); |
243 | 0 | } |
244 | | |
245 | 0 | void RuntimeProfile::compute_time_in_profile() { |
246 | 0 | compute_time_in_profile(total_time_counter()->value()); |
247 | 0 | } |
248 | | |
249 | 0 | void RuntimeProfile::compute_time_in_profile(int64_t total) { |
250 | 0 | if (total == 0) { |
251 | 0 | return; |
252 | 0 | } |
253 | | |
254 | | // Add all the total times in all the children |
255 | 0 | int64_t total_child_time = 0; |
256 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
257 | |
|
258 | 0 | for (int i = 0; i < _children.size(); ++i) { |
259 | 0 | total_child_time += _children[i].first->total_time_counter()->value(); |
260 | 0 | } |
261 | |
|
262 | 0 | int64_t local_time = total_time_counter()->value() - total_child_time; |
263 | | // Counters have some margin, set to 0 if it was negative. |
264 | 0 | local_time = std::max<int64_t>(0L, local_time); |
265 | 0 | _local_time_percent = static_cast<double>(local_time) / total; |
266 | 0 | _local_time_percent = std::min(1.0, _local_time_percent) * 100; |
267 | | |
268 | | // Recurse on children |
269 | 0 | for (int i = 0; i < _children.size(); ++i) { |
270 | 0 | _children[i].first->compute_time_in_profile(total); |
271 | 0 | } |
272 | 0 | } |
273 | | |
274 | 89 | RuntimeProfile* RuntimeProfile::create_child(const std::string& name, bool indent, bool prepend) { |
275 | 89 | std::lock_guard<std::mutex> l(_children_lock); |
276 | 89 | DCHECK(_child_map.find(name) == _child_map.end()); |
277 | 89 | RuntimeProfile* child = _pool->add(new RuntimeProfile(name)); |
278 | 89 | if (this->is_set_metadata()) { |
279 | 0 | child->set_metadata(this->metadata()); |
280 | 0 | } |
281 | 89 | if (this->is_set_sink()) { |
282 | 0 | child->set_is_sink(this->is_sink()); |
283 | 0 | } |
284 | 89 | if (_children.empty()) { |
285 | 62 | add_child_unlock(child, indent, nullptr); |
286 | 62 | } else { |
287 | 27 | ChildVector::iterator pos = prepend ? _children.begin() : _children.end(); |
288 | 27 | add_child_unlock(child, indent, (*pos).first); |
289 | 27 | } |
290 | 89 | return child; |
291 | 89 | } |
292 | | |
293 | 0 | void RuntimeProfile::insert_child_head(doris::RuntimeProfile* child, bool indent) { |
294 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
295 | 0 | DCHECK(child != nullptr); |
296 | 0 | _child_map[child->_name] = child; |
297 | |
|
298 | 0 | auto it = _children.begin(); |
299 | 0 | _children.insert(it, std::make_pair(child, indent)); |
300 | 0 | } |
301 | | |
302 | 91 | void RuntimeProfile::add_child_unlock(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
303 | 91 | DCHECK(child != nullptr); |
304 | 91 | _child_map[child->_name] = child; |
305 | | |
306 | 91 | if (loc == nullptr) { |
307 | 64 | _children.push_back(std::make_pair(child, indent)); |
308 | 64 | } else { |
309 | 27 | for (ChildVector::iterator it = _children.begin(); it != _children.end(); ++it) { |
310 | 27 | if (it->first == loc) { |
311 | 27 | _children.insert(it, std::make_pair(child, indent)); |
312 | 27 | return; |
313 | 27 | } |
314 | 27 | } |
315 | 0 | DCHECK(false) << "Invalid loc"; |
316 | 0 | } |
317 | 91 | } |
318 | | |
319 | 2 | void RuntimeProfile::add_child(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
320 | 2 | std::lock_guard<std::mutex> l(_children_lock); |
321 | 2 | add_child_unlock(child, indent, loc); |
322 | 2 | } |
323 | | |
324 | 0 | void RuntimeProfile::get_children(std::vector<RuntimeProfile*>* children) { |
325 | 0 | children->clear(); |
326 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
327 | |
|
328 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
329 | 0 | children->push_back(i->second); |
330 | 0 | } |
331 | 0 | } |
332 | | |
333 | 0 | void RuntimeProfile::get_all_children(std::vector<RuntimeProfile*>* children) { |
334 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
335 | |
|
336 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
337 | 0 | children->push_back(i->second); |
338 | 0 | i->second->get_all_children(children); |
339 | 0 | } |
340 | 0 | } |
341 | | |
342 | 2 | void RuntimeProfile::add_info_string(const std::string& key, const std::string& value) { |
343 | 2 | std::lock_guard<std::mutex> l(_info_strings_lock); |
344 | 2 | InfoStrings::iterator it = _info_strings.find(key); |
345 | | |
346 | 2 | if (it == _info_strings.end()) { |
347 | 2 | _info_strings.insert(std::make_pair(key, value)); |
348 | 2 | _info_strings_display_order.push_back(key); |
349 | 2 | } else { |
350 | 0 | it->second = value; |
351 | 0 | } |
352 | 2 | } |
353 | | |
354 | 0 | const std::string* RuntimeProfile::get_info_string(const std::string& key) { |
355 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
356 | 0 | InfoStrings::const_iterator it = _info_strings.find(key); |
357 | |
|
358 | 0 | if (it == _info_strings.end()) { |
359 | 0 | return nullptr; |
360 | 0 | } |
361 | | |
362 | 0 | return &it->second; |
363 | 0 | } |
364 | | |
365 | | #define ADD_COUNTER_IMPL(NAME, T) \ |
366 | | RuntimeProfile::T* RuntimeProfile::NAME(const std::string& name, TUnit::type unit, \ |
367 | | const std::string& parent_counter_name, \ |
368 | 4 | int64_t level) { \ |
369 | 4 | DCHECK_EQ(_is_averaged_profile, false); \ |
370 | 4 | std::lock_guard<std::mutex> l(_counter_map_lock); \ |
371 | 4 | if (_counter_map.find(name) != _counter_map.end()) { \ |
372 | 0 | return reinterpret_cast<T*>(_counter_map[name]); \ |
373 | 0 | } \ |
374 | 4 | DCHECK(parent_counter_name == ROOT_COUNTER || \ |
375 | 4 | _counter_map.find(parent_counter_name) != _counter_map.end()); \ |
376 | 4 | T* counter = _pool->add(new T(unit, level)); \ |
377 | 4 | _counter_map[name] = counter; \ |
378 | 4 | std::set<std::string>* child_counters = \ |
379 | 4 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); \ |
380 | 4 | child_counters->insert(name); \ |
381 | 4 | return counter; \ |
382 | 4 | } |
383 | | |
384 | | //ADD_COUNTER_IMPL(AddCounter, Counter); |
385 | | ADD_COUNTER_IMPL(AddHighWaterMarkCounter, HighWaterMarkCounter); |
386 | | //ADD_COUNTER_IMPL(AddConcurrentTimerCounter, ConcurrentTimerCounter); |
387 | | |
388 | | std::shared_ptr<RuntimeProfile::HighWaterMarkCounter> RuntimeProfile::AddSharedHighWaterMarkCounter( |
389 | 0 | const std::string& name, TUnit::type unit, const std::string& parent_counter_name) { |
390 | 0 | DCHECK_EQ(_is_averaged_profile, false); |
391 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
392 | 0 | if (_shared_counter_pool.find(name) != _shared_counter_pool.end()) { |
393 | 0 | return _shared_counter_pool[name]; |
394 | 0 | } |
395 | 0 | DCHECK(parent_counter_name == ROOT_COUNTER || |
396 | 0 | _counter_map.find(parent_counter_name) != _counter_map.end()); |
397 | 0 | std::shared_ptr<HighWaterMarkCounter> counter = std::make_shared<HighWaterMarkCounter>(unit); |
398 | 0 | _shared_counter_pool[name] = counter; |
399 | |
|
400 | 0 | DCHECK(_counter_map.find(name) == _counter_map.end()) |
401 | 0 | << "already has a raw counter named " << name; |
402 | | |
403 | | // it's OK to insert shared counter to _counter_map, cuz _counter_map is not the owner of counters |
404 | 0 | _counter_map[name] = counter.get(); |
405 | 0 | std::set<std::string>* child_counters = |
406 | 0 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
407 | 0 | child_counters->insert(name); |
408 | 0 | return counter; |
409 | 0 | } |
410 | | |
411 | | RuntimeProfile::Counter* RuntimeProfile::add_counter(const std::string& name, TUnit::type type, |
412 | | const std::string& parent_counter_name, |
413 | 6.43k | int64_t level) { |
414 | 6.43k | std::lock_guard<std::mutex> l(_counter_map_lock); |
415 | | |
416 | | // TODO(yingchun): Can we ensure that 'name' is not exist in '_counter_map'? Use CHECK instead? |
417 | 6.43k | if (_counter_map.find(name) != _counter_map.end()) { |
418 | | // TODO: should we make sure that we don't return existing derived counters? |
419 | 40 | return _counter_map[name]; |
420 | 40 | } |
421 | | |
422 | 6.39k | DCHECK(parent_counter_name == ROOT_COUNTER || |
423 | 6.39k | _counter_map.find(parent_counter_name) != _counter_map.end()); |
424 | 6.39k | Counter* counter = _pool->add(new Counter(type, 0, level)); |
425 | 6.39k | _counter_map[name] = counter; |
426 | 6.39k | std::set<std::string>* child_counters = |
427 | 6.39k | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
428 | 6.39k | child_counters->insert(name); |
429 | 6.39k | return counter; |
430 | 6.43k | } |
431 | | |
432 | | RuntimeProfile::NonZeroCounter* RuntimeProfile::add_nonzero_counter( |
433 | | const std::string& name, TUnit::type type, const std::string& parent_counter_name, |
434 | 0 | int64_t level) { |
435 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
436 | 0 | if (_counter_map.find(name) != _counter_map.end()) { |
437 | 0 | DCHECK(dynamic_cast<NonZeroCounter*>(_counter_map[name])); |
438 | 0 | return static_cast<NonZeroCounter*>(_counter_map[name]); |
439 | 0 | } |
440 | | |
441 | 0 | DCHECK(parent_counter_name == ROOT_COUNTER || |
442 | 0 | _counter_map.find(parent_counter_name) != _counter_map.end()); |
443 | 0 | NonZeroCounter* counter = _pool->add(new NonZeroCounter(type, level, parent_counter_name)); |
444 | 0 | _counter_map[name] = counter; |
445 | 0 | std::set<std::string>* child_counters = |
446 | 0 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
447 | 0 | child_counters->insert(name); |
448 | 0 | return counter; |
449 | 0 | } |
450 | | |
451 | | RuntimeProfile::DerivedCounter* RuntimeProfile::add_derived_counter( |
452 | | const std::string& name, TUnit::type type, const DerivedCounterFunction& counter_fn, |
453 | 2 | const std::string& parent_counter_name) { |
454 | 2 | std::lock_guard<std::mutex> l(_counter_map_lock); |
455 | | |
456 | 2 | if (_counter_map.find(name) != _counter_map.end()) { |
457 | 0 | return nullptr; |
458 | 0 | } |
459 | | |
460 | 2 | DerivedCounter* counter = _pool->add(new DerivedCounter(type, counter_fn)); |
461 | 2 | _counter_map[name] = counter; |
462 | 2 | std::set<std::string>* child_counters = |
463 | 2 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
464 | 2 | child_counters->insert(name); |
465 | 2 | return counter; |
466 | 2 | } |
467 | | |
468 | 301 | RuntimeProfile::Counter* RuntimeProfile::get_counter(const std::string& name) { |
469 | 301 | std::lock_guard<std::mutex> l(_counter_map_lock); |
470 | | |
471 | 301 | if (_counter_map.find(name) != _counter_map.end()) { |
472 | 299 | return _counter_map[name]; |
473 | 299 | } |
474 | | |
475 | 2 | return nullptr; |
476 | 301 | } |
477 | | |
478 | 0 | void RuntimeProfile::get_counters(const std::string& name, std::vector<Counter*>* counters) { |
479 | 0 | Counter* c = get_counter(name); |
480 | |
|
481 | 0 | if (c != nullptr) { |
482 | 0 | counters->push_back(c); |
483 | 0 | } |
484 | |
|
485 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
486 | |
|
487 | 0 | for (int i = 0; i < _children.size(); ++i) { |
488 | 0 | _children[i].first->get_counters(name, counters); |
489 | 0 | } |
490 | 0 | } |
491 | | |
492 | | // Print the profile: |
493 | | // 1. Profile Name |
494 | | // 2. Info Strings |
495 | | // 3. Counters |
496 | | // 4. Children |
497 | 0 | void RuntimeProfile::pretty_print(std::ostream* s, const std::string& prefix) const { |
498 | 0 | std::ostream& stream = *s; |
499 | | |
500 | | // create copy of _counter_map and _child_counter_map so we don't need to hold lock |
501 | | // while we call value() on the counters |
502 | 0 | CounterMap counter_map; |
503 | 0 | ChildCounterMap child_counter_map; |
504 | 0 | { |
505 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
506 | 0 | counter_map = _counter_map; |
507 | 0 | child_counter_map = _child_counter_map; |
508 | 0 | } |
509 | |
|
510 | 0 | std::map<std::string, Counter*>::const_iterator total_time = counter_map.find("TotalTime"); |
511 | 0 | DCHECK(total_time != counter_map.end()); |
512 | |
|
513 | 0 | stream.flags(std::ios::fixed); |
514 | 0 | stream << prefix << _name << ":"; |
515 | |
|
516 | 0 | if (total_time->second->value() != 0) { |
517 | 0 | stream << "(Active: " |
518 | 0 | << PrettyPrinter::print(total_time->second->value(), total_time->second->type()) |
519 | 0 | << ", non-child: " << std::setprecision(2) << _local_time_percent << "%)"; |
520 | 0 | } |
521 | |
|
522 | 0 | stream << std::endl; |
523 | |
|
524 | 0 | { |
525 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
526 | 0 | for (const std::string& key : _info_strings_display_order) { |
527 | 0 | stream << prefix << " - " << key << ": " << _info_strings.find(key)->second |
528 | 0 | << std::endl; |
529 | 0 | } |
530 | 0 | } |
531 | |
|
532 | 0 | { |
533 | | // Print all the event timers as the following: |
534 | | // <EventKey> Timeline: 2s719ms |
535 | | // - Event 1: 6.522us (6.522us) |
536 | | // - Event 2: 2s288ms (2s288ms) |
537 | | // - Event 3: 2s410ms (121.138ms) |
538 | | // The times in parentheses are the time elapsed since the last event. |
539 | 0 | std::lock_guard<std::mutex> l(_event_sequences_lock); |
540 | 0 | for (const EventSequenceMap::value_type& event_sequence : _event_sequence_map) { |
541 | 0 | stream << prefix << " " << event_sequence.first << ": " |
542 | 0 | << PrettyPrinter::print(event_sequence.second->elapsed_time(), TUnit::TIME_NS) |
543 | 0 | << std::endl; |
544 | |
|
545 | 0 | int64_t last = 0L; |
546 | 0 | for (const EventSequence::Event& event : event_sequence.second->events()) { |
547 | 0 | stream << prefix << " - " << event.first << ": " |
548 | 0 | << PrettyPrinter::print(event.second, TUnit::TIME_NS) << " (" |
549 | 0 | << PrettyPrinter::print(event.second - last, TUnit::TIME_NS) << ")" |
550 | 0 | << std::endl; |
551 | 0 | last = event.second; |
552 | 0 | } |
553 | 0 | } |
554 | 0 | } |
555 | |
|
556 | 0 | RuntimeProfile::print_child_counters(prefix, ROOT_COUNTER, counter_map, child_counter_map, s); |
557 | | |
558 | | // create copy of _children so we don't need to hold lock while we call |
559 | | // pretty_print() on the children |
560 | 0 | ChildVector children; |
561 | 0 | { |
562 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
563 | 0 | children = _children; |
564 | 0 | } |
565 | |
|
566 | 0 | for (int i = 0; i < children.size(); ++i) { |
567 | 0 | RuntimeProfile* profile = children[i].first; |
568 | 0 | bool indent = children[i].second; |
569 | 0 | profile->pretty_print(s, prefix + (indent ? " " : "")); |
570 | 0 | } |
571 | 0 | } |
572 | | |
573 | 0 | void RuntimeProfile::to_thrift(TRuntimeProfileTree* tree) { |
574 | 0 | tree->nodes.clear(); |
575 | 0 | to_thrift(&tree->nodes); |
576 | 0 | } |
577 | | |
578 | 0 | void RuntimeProfile::to_thrift(std::vector<TRuntimeProfileNode>* nodes) { |
579 | 0 | int index = nodes->size(); |
580 | 0 | nodes->push_back(TRuntimeProfileNode()); |
581 | 0 | TRuntimeProfileNode& node = (*nodes)[index]; |
582 | 0 | node.name = _name; |
583 | 0 | node.metadata = _metadata; |
584 | 0 | node.timestamp = _timestamp; |
585 | 0 | node.indent = true; |
586 | 0 | if (this->is_set_sink()) { |
587 | 0 | node.__set_is_sink(this->is_sink()); |
588 | 0 | } |
589 | 0 | CounterMap counter_map; |
590 | 0 | { |
591 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
592 | 0 | counter_map = _counter_map; |
593 | 0 | node.child_counters_map = _child_counter_map; |
594 | 0 | } |
595 | |
|
596 | 0 | for (auto&& [name, counter] : counter_map) { |
597 | 0 | counter->to_thrift(name, node.counters, node.child_counters_map); |
598 | 0 | } |
599 | |
|
600 | 0 | { |
601 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
602 | 0 | node.info_strings = _info_strings; |
603 | 0 | node.info_strings_display_order = _info_strings_display_order; |
604 | 0 | } |
605 | |
|
606 | 0 | ChildVector children; |
607 | 0 | { |
608 | | // _children may be modified during to_thrift(), |
609 | | // so we have to lock and copy _children to avoid race condition |
610 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
611 | 0 | children = _children; |
612 | 0 | } |
613 | 0 | node.num_children = children.size(); |
614 | 0 | nodes->reserve(nodes->size() + children.size()); |
615 | |
|
616 | 0 | for (int i = 0; i < children.size(); ++i) { |
617 | 0 | int child_idx = nodes->size(); |
618 | 0 | children[i].first->to_thrift(nodes); |
619 | | // fix up indentation flag |
620 | 0 | (*nodes)[child_idx].indent = children[i].second; |
621 | 0 | } |
622 | 0 | } |
623 | | |
624 | | int64_t RuntimeProfile::units_per_second(const RuntimeProfile::Counter* total_counter, |
625 | 0 | const RuntimeProfile::Counter* timer) { |
626 | 0 | DCHECK(total_counter->type() == TUnit::BYTES || total_counter->type() == TUnit::UNIT); |
627 | 0 | DCHECK(timer->type() == TUnit::TIME_NS); |
628 | |
|
629 | 0 | if (timer->value() == 0) { |
630 | 0 | return 0; |
631 | 0 | } |
632 | | |
633 | 0 | double secs = static_cast<double>(timer->value()) / 1000.0 / 1000.0 / 1000.0; |
634 | 0 | return int64_t(total_counter->value() / secs); |
635 | 0 | } |
636 | | |
637 | 0 | int64_t RuntimeProfile::counter_sum(const std::vector<Counter*>* counters) { |
638 | 0 | int64_t value = 0; |
639 | |
|
640 | 0 | for (int i = 0; i < counters->size(); ++i) { |
641 | 0 | value += (*counters)[i]->value(); |
642 | 0 | } |
643 | |
|
644 | 0 | return value; |
645 | 0 | } |
646 | | |
647 | | RuntimeProfile::Counter* RuntimeProfile::add_rate_counter(const std::string& name, |
648 | 2 | Counter* src_counter) { |
649 | 2 | TUnit::type dst_type; |
650 | | |
651 | 2 | switch (src_counter->type()) { |
652 | 0 | case TUnit::BYTES: |
653 | 0 | dst_type = TUnit::BYTES_PER_SECOND; |
654 | 0 | break; |
655 | | |
656 | 2 | case TUnit::UNIT: |
657 | 2 | dst_type = TUnit::UNIT_PER_SECOND; |
658 | 2 | break; |
659 | | |
660 | 0 | default: |
661 | 0 | DCHECK(false) << "Unsupported src counter type: " << src_counter->type(); |
662 | 0 | return nullptr; |
663 | 2 | } |
664 | | |
665 | 2 | Counter* dst_counter = add_counter(name, dst_type); |
666 | 2 | return dst_counter; |
667 | 2 | } |
668 | | |
669 | | RuntimeProfile::Counter* RuntimeProfile::add_rate_counter(const std::string& name, SampleFn fn, |
670 | 0 | TUnit::type dst_type) { |
671 | 0 | return add_counter(name, dst_type); |
672 | 0 | } |
673 | | |
674 | | RuntimeProfile::Counter* RuntimeProfile::add_sampling_counter(const std::string& name, |
675 | 0 | Counter* src_counter) { |
676 | 0 | DCHECK(src_counter->type() == TUnit::UNIT); |
677 | 0 | return add_counter(name, TUnit::DOUBLE_VALUE); |
678 | 0 | } |
679 | | |
680 | | RuntimeProfile::Counter* RuntimeProfile::add_sampling_counter(const std::string& name, |
681 | 0 | SampleFn sample_fn) { |
682 | 0 | return add_counter(name, TUnit::DOUBLE_VALUE); |
683 | 0 | } |
684 | | |
685 | 0 | RuntimeProfile::EventSequence* RuntimeProfile::add_event_sequence(const std::string& name) { |
686 | 0 | std::lock_guard<std::mutex> l(_event_sequences_lock); |
687 | 0 | EventSequenceMap::iterator timer_it = _event_sequence_map.find(name); |
688 | |
|
689 | 0 | if (timer_it != _event_sequence_map.end()) { |
690 | 0 | return timer_it->second; |
691 | 0 | } |
692 | | |
693 | 0 | EventSequence* timer = _pool->add(new EventSequence()); |
694 | 0 | _event_sequence_map[name] = timer; |
695 | 0 | return timer; |
696 | 0 | } |
697 | | |
698 | | void RuntimeProfile::print_child_counters(const std::string& prefix, |
699 | | const std::string& counter_name, |
700 | | const CounterMap& counter_map, |
701 | | const ChildCounterMap& child_counter_map, |
702 | 0 | std::ostream* s) { |
703 | 0 | std::ostream& stream = *s; |
704 | 0 | ChildCounterMap::const_iterator itr = child_counter_map.find(counter_name); |
705 | |
|
706 | 0 | if (itr != child_counter_map.end()) { |
707 | 0 | const std::set<std::string>& child_counters = itr->second; |
708 | 0 | for (const std::string& child_counter : child_counters) { |
709 | 0 | CounterMap::const_iterator iter = counter_map.find(child_counter); |
710 | 0 | DCHECK(iter != counter_map.end()); |
711 | 0 | stream << prefix << " - " << iter->first << ": " |
712 | 0 | << PrettyPrinter::print(iter->second->value(), iter->second->type()) |
713 | 0 | << std::endl; |
714 | 0 | RuntimeProfile::print_child_counters(prefix + " ", child_counter, counter_map, |
715 | 0 | child_counter_map, s); |
716 | 0 | } |
717 | 0 | } |
718 | 0 | } |
719 | | |
720 | | } // namespace doris |