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