/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 | | |
32 | | #include "common/object_pool.h" |
33 | | #include "util/container_util.hpp" |
34 | | |
35 | | namespace doris { |
36 | | |
37 | | // Thread counters name |
38 | | static const std::string THREAD_TOTAL_TIME = "TotalWallClockTime"; |
39 | | static const std::string THREAD_VOLUNTARY_CONTEXT_SWITCHES = "VoluntaryContextSwitches"; |
40 | | static const std::string THREAD_INVOLUNTARY_CONTEXT_SWITCHES = "InvoluntaryContextSwitches"; |
41 | | |
42 | | // The root counter name for all top level counters. |
43 | | static const std::string ROOT_COUNTER; |
44 | | |
45 | | RuntimeProfile::RuntimeProfile(const std::string& name, bool is_averaged_profile) |
46 | | : _pool(new ObjectPool()), |
47 | | _name(name), |
48 | | _metadata(-1), |
49 | | _timestamp(-1), |
50 | | _is_averaged_profile(is_averaged_profile), |
51 | | _counter_total_time(TUnit::TIME_NS, 0, 3), |
52 | 22.7k | _local_time_percent(0) { |
53 | | // TotalTime counter has level3 to disable it from plan profile, because |
54 | | // it contains its child running time, we use exec time instead. |
55 | 22.7k | _counter_map["TotalTime"] = &_counter_total_time; |
56 | 22.7k | } |
57 | | |
58 | 22.6k | RuntimeProfile::~RuntimeProfile() = default; |
59 | | |
60 | 0 | void RuntimeProfile::merge(RuntimeProfile* other) { |
61 | 0 | DCHECK(other != nullptr); |
62 | | |
63 | | // Merge this level |
64 | 0 | { |
65 | 0 | CounterMap::iterator dst_iter; |
66 | 0 | CounterMap::const_iterator src_iter; |
67 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
68 | 0 | std::lock_guard<std::mutex> m(other->_counter_map_lock); |
69 | |
|
70 | 0 | for (src_iter = other->_counter_map.begin(); src_iter != other->_counter_map.end(); |
71 | 0 | ++src_iter) { |
72 | 0 | dst_iter = _counter_map.find(src_iter->first); |
73 | |
|
74 | 0 | if (dst_iter == _counter_map.end()) { |
75 | 0 | _counter_map[src_iter->first] = _pool->add( |
76 | 0 | new Counter(src_iter->second->type(), src_iter->second->value())); |
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 | 92 | RuntimeProfile* RuntimeProfile::create_child(const std::string& name, bool indent, bool prepend) { |
276 | 92 | std::lock_guard<std::mutex> l(_children_lock); |
277 | 92 | DCHECK(_child_map.find(name) == _child_map.end()) << ", name: " << name; |
278 | 92 | RuntimeProfile* child = _pool->add(new RuntimeProfile(name)); |
279 | 92 | if (this->is_set_metadata()) { |
280 | 0 | child->set_metadata(this->metadata()); |
281 | 0 | } |
282 | 92 | if (this->is_set_sink()) { |
283 | 0 | child->set_is_sink(this->is_sink()); |
284 | 0 | } |
285 | 92 | if (_children.empty()) { |
286 | 64 | add_child_unlock(child, indent, nullptr); |
287 | 64 | } else { |
288 | 28 | auto* pos = prepend ? _children.begin()->first : nullptr; |
289 | 28 | add_child_unlock(child, indent, pos); |
290 | 28 | } |
291 | 92 | return child; |
292 | 92 | } |
293 | | |
294 | 0 | void RuntimeProfile::insert_child_head(doris::RuntimeProfile* child, bool indent) { |
295 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
296 | 0 | DCHECK(child != nullptr); |
297 | 0 | _child_map[child->_name] = child; |
298 | |
|
299 | 0 | auto it = _children.begin(); |
300 | 0 | _children.insert(it, std::make_pair(child, indent)); |
301 | 0 | } |
302 | | |
303 | 98 | void RuntimeProfile::add_child_unlock(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
304 | 98 | DCHECK(child != nullptr); |
305 | 98 | _child_map[child->_name] = child; |
306 | | |
307 | 98 | if (loc == nullptr) { |
308 | 70 | _children.push_back(std::make_pair(child, indent)); |
309 | 70 | } else { |
310 | 28 | for (ChildVector::iterator it = _children.begin(); it != _children.end(); ++it) { |
311 | 28 | if (it->first == loc) { |
312 | 28 | _children.insert(it, std::make_pair(child, indent)); |
313 | 28 | return; |
314 | 28 | } |
315 | 28 | } |
316 | 0 | DCHECK(false) << "Invalid loc"; |
317 | 0 | } |
318 | 98 | } |
319 | | |
320 | 6 | void RuntimeProfile::add_child(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
321 | 6 | std::lock_guard<std::mutex> l(_children_lock); |
322 | 6 | add_child_unlock(child, indent, loc); |
323 | 6 | } |
324 | | |
325 | 0 | void RuntimeProfile::get_children(std::vector<RuntimeProfile*>* children) { |
326 | 0 | children->clear(); |
327 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
328 | |
|
329 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
330 | 0 | children->push_back(i->second); |
331 | 0 | } |
332 | 0 | } |
333 | | |
334 | 0 | void RuntimeProfile::get_all_children(std::vector<RuntimeProfile*>* children) { |
335 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
336 | |
|
337 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
338 | 0 | children->push_back(i->second); |
339 | 0 | i->second->get_all_children(children); |
340 | 0 | } |
341 | 0 | } |
342 | | |
343 | 3 | void RuntimeProfile::add_info_string(const std::string& key, const std::string& value) { |
344 | 3 | std::lock_guard<std::mutex> l(_info_strings_lock); |
345 | 3 | InfoStrings::iterator it = _info_strings.find(key); |
346 | | |
347 | 3 | if (it == _info_strings.end()) { |
348 | 3 | _info_strings.insert(std::make_pair(key, value)); |
349 | 3 | _info_strings_display_order.push_back(key); |
350 | 3 | } else { |
351 | 0 | it->second = value; |
352 | 0 | } |
353 | 3 | } |
354 | | |
355 | 0 | const std::string* RuntimeProfile::get_info_string(const std::string& key) { |
356 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
357 | 0 | InfoStrings::const_iterator it = _info_strings.find(key); |
358 | |
|
359 | 0 | if (it == _info_strings.end()) { |
360 | 0 | return nullptr; |
361 | 0 | } |
362 | | |
363 | 0 | return &it->second; |
364 | 0 | } |
365 | | |
366 | | #define ADD_COUNTER_IMPL(NAME, T) \ |
367 | | RuntimeProfile::T* RuntimeProfile::NAME(const std::string& name, TUnit::type unit, \ |
368 | | const std::string& parent_counter_name, \ |
369 | 6 | int64_t level) { \ |
370 | 6 | DCHECK_EQ(_is_averaged_profile, false); \ |
371 | 6 | std::lock_guard<std::mutex> l(_counter_map_lock); \ |
372 | 6 | if (_counter_map.find(name) != _counter_map.end()) { \ |
373 | 0 | return reinterpret_cast<T*>(_counter_map[name]); \ |
374 | 0 | } \ |
375 | 6 | DCHECK(parent_counter_name == ROOT_COUNTER || \ |
376 | 6 | _counter_map.find(parent_counter_name) != _counter_map.end()); \ |
377 | 6 | T* counter = _pool->add(new T(unit, level)); \ |
378 | 6 | _counter_map[name] = counter; \ |
379 | 6 | std::set<std::string>* child_counters = \ |
380 | 6 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); \ |
381 | 6 | child_counters->insert(name); \ |
382 | 6 | return counter; \ |
383 | 6 | } |
384 | | |
385 | | //ADD_COUNTER_IMPL(AddCounter, Counter); |
386 | | ADD_COUNTER_IMPL(AddHighWaterMarkCounter, HighWaterMarkCounter); |
387 | | //ADD_COUNTER_IMPL(AddConcurrentTimerCounter, ConcurrentTimerCounter); |
388 | | |
389 | | std::shared_ptr<RuntimeProfile::HighWaterMarkCounter> RuntimeProfile::AddSharedHighWaterMarkCounter( |
390 | 0 | const std::string& name, TUnit::type unit, const std::string& parent_counter_name) { |
391 | 0 | DCHECK_EQ(_is_averaged_profile, false); |
392 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
393 | 0 | if (_shared_counter_pool.find(name) != _shared_counter_pool.end()) { |
394 | 0 | return _shared_counter_pool[name]; |
395 | 0 | } |
396 | 0 | DCHECK(parent_counter_name == ROOT_COUNTER || |
397 | 0 | _counter_map.find(parent_counter_name) != _counter_map.end()); |
398 | 0 | std::shared_ptr<HighWaterMarkCounter> counter = std::make_shared<HighWaterMarkCounter>(unit); |
399 | 0 | _shared_counter_pool[name] = counter; |
400 | |
|
401 | 0 | DCHECK(_counter_map.find(name) == _counter_map.end()) |
402 | 0 | << "already has a raw counter named " << name; |
403 | | |
404 | | // it's OK to insert shared counter to _counter_map, cuz _counter_map is not the owner of counters |
405 | 0 | _counter_map[name] = counter.get(); |
406 | 0 | std::set<std::string>* child_counters = |
407 | 0 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
408 | 0 | child_counters->insert(name); |
409 | 0 | return counter; |
410 | 0 | } |
411 | | |
412 | | RuntimeProfile::Counter* RuntimeProfile::add_counter(const std::string& name, TUnit::type type, |
413 | | const std::string& parent_counter_name, |
414 | 4.05k | int64_t level) { |
415 | 4.05k | std::lock_guard<std::mutex> l(_counter_map_lock); |
416 | | |
417 | | // TODO(yingchun): Can we ensure that 'name' is not exist in '_counter_map'? Use CHECK instead? |
418 | 4.05k | if (_counter_map.find(name) != _counter_map.end()) { |
419 | | // TODO: should we make sure that we don't return existing derived counters? |
420 | 31 | return _counter_map[name]; |
421 | 31 | } |
422 | | |
423 | 4.02k | DCHECK(parent_counter_name == ROOT_COUNTER || |
424 | 4.02k | _counter_map.find(parent_counter_name) != _counter_map.end()); |
425 | 4.02k | Counter* counter = _pool->add(new Counter(type, 0, level)); |
426 | 4.02k | _counter_map[name] = counter; |
427 | 4.02k | std::set<std::string>* child_counters = |
428 | 4.02k | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
429 | 4.02k | child_counters->insert(name); |
430 | 4.02k | return counter; |
431 | 4.05k | } |
432 | | |
433 | | RuntimeProfile::NonZeroCounter* RuntimeProfile::add_nonzero_counter( |
434 | | const std::string& name, TUnit::type type, const std::string& parent_counter_name, |
435 | 0 | int64_t level) { |
436 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
437 | 0 | if (_counter_map.find(name) != _counter_map.end()) { |
438 | 0 | DCHECK(dynamic_cast<NonZeroCounter*>(_counter_map[name])); |
439 | 0 | return static_cast<NonZeroCounter*>(_counter_map[name]); |
440 | 0 | } |
441 | | |
442 | 0 | DCHECK(parent_counter_name == ROOT_COUNTER || |
443 | 0 | _counter_map.find(parent_counter_name) != _counter_map.end()); |
444 | 0 | NonZeroCounter* counter = _pool->add(new NonZeroCounter(type, level, parent_counter_name)); |
445 | 0 | _counter_map[name] = counter; |
446 | 0 | std::set<std::string>* child_counters = |
447 | 0 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
448 | 0 | child_counters->insert(name); |
449 | 0 | return counter; |
450 | 0 | } |
451 | | |
452 | | RuntimeProfile::DerivedCounter* RuntimeProfile::add_derived_counter( |
453 | | const std::string& name, TUnit::type type, const DerivedCounterFunction& counter_fn, |
454 | 0 | const std::string& parent_counter_name) { |
455 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
456 | |
|
457 | 0 | if (_counter_map.find(name) != _counter_map.end()) { |
458 | 0 | return nullptr; |
459 | 0 | } |
460 | | |
461 | 0 | DerivedCounter* counter = _pool->add(new DerivedCounter(type, counter_fn)); |
462 | 0 | _counter_map[name] = counter; |
463 | 0 | std::set<std::string>* child_counters = |
464 | 0 | find_or_insert(&_child_counter_map, parent_counter_name, std::set<std::string>()); |
465 | 0 | child_counters->insert(name); |
466 | 0 | return counter; |
467 | 0 | } |
468 | | |
469 | 93 | RuntimeProfile::Counter* RuntimeProfile::get_counter(const std::string& name) { |
470 | 93 | std::lock_guard<std::mutex> l(_counter_map_lock); |
471 | | |
472 | 93 | if (_counter_map.find(name) != _counter_map.end()) { |
473 | 91 | return _counter_map[name]; |
474 | 91 | } |
475 | | |
476 | 2 | return nullptr; |
477 | 93 | } |
478 | | |
479 | 0 | void RuntimeProfile::get_counters(const std::string& name, std::vector<Counter*>* counters) { |
480 | 0 | Counter* c = get_counter(name); |
481 | |
|
482 | 0 | if (c != nullptr) { |
483 | 0 | counters->push_back(c); |
484 | 0 | } |
485 | |
|
486 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
487 | |
|
488 | 0 | for (int i = 0; i < _children.size(); ++i) { |
489 | 0 | _children[i].first->get_counters(name, counters); |
490 | 0 | } |
491 | 0 | } |
492 | | |
493 | | // Print the profile: |
494 | | // 1. Profile Name |
495 | | // 2. Info Strings |
496 | | // 3. Counters |
497 | | // 4. Children |
498 | 0 | void RuntimeProfile::pretty_print(std::ostream* s, const std::string& prefix) const { |
499 | 0 | std::ostream& stream = *s; |
500 | | |
501 | | // create copy of _counter_map and _child_counter_map so we don't need to hold lock |
502 | | // while we call value() on the counters |
503 | 0 | CounterMap counter_map; |
504 | 0 | ChildCounterMap child_counter_map; |
505 | 0 | { |
506 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
507 | 0 | counter_map = _counter_map; |
508 | 0 | child_counter_map = _child_counter_map; |
509 | 0 | } |
510 | |
|
511 | 0 | std::map<std::string, Counter*>::const_iterator total_time = counter_map.find("TotalTime"); |
512 | 0 | DCHECK(total_time != counter_map.end()); |
513 | |
|
514 | 0 | stream.flags(std::ios::fixed); |
515 | 0 | stream << prefix << _name << ":"; |
516 | |
|
517 | 0 | if (total_time->second->value() != 0) { |
518 | 0 | stream << "(Active: " |
519 | 0 | << PrettyPrinter::print(total_time->second->value(), total_time->second->type()) |
520 | 0 | << ", non-child: " << std::setprecision(2) << _local_time_percent << "%)"; |
521 | 0 | } |
522 | |
|
523 | 0 | stream << std::endl; |
524 | |
|
525 | 0 | { |
526 | 0 | std::lock_guard<std::mutex> l(_info_strings_lock); |
527 | 0 | for (const std::string& key : _info_strings_display_order) { |
528 | 0 | stream << prefix << " - " << key << ": " << _info_strings.find(key)->second |
529 | 0 | << std::endl; |
530 | 0 | } |
531 | 0 | } |
532 | |
|
533 | 0 | { |
534 | | // Print all the event timers as the following: |
535 | | // <EventKey> Timeline: 2s719ms |
536 | | // - Event 1: 6.522us (6.522us) |
537 | | // - Event 2: 2s288ms (2s288ms) |
538 | | // - Event 3: 2s410ms (121.138ms) |
539 | | // The times in parentheses are the time elapsed since the last event. |
540 | 0 | std::lock_guard<std::mutex> l(_event_sequences_lock); |
541 | 0 | for (const EventSequenceMap::value_type& event_sequence : _event_sequence_map) { |
542 | 0 | stream << prefix << " " << event_sequence.first << ": " |
543 | 0 | << PrettyPrinter::print(event_sequence.second->elapsed_time(), TUnit::TIME_NS) |
544 | 0 | << std::endl; |
545 | |
|
546 | 0 | int64_t last = 0L; |
547 | 0 | for (const EventSequence::Event& event : event_sequence.second->events()) { |
548 | 0 | stream << prefix << " - " << event.first << ": " |
549 | 0 | << PrettyPrinter::print(event.second, TUnit::TIME_NS) << " (" |
550 | 0 | << PrettyPrinter::print(event.second - last, TUnit::TIME_NS) << ")" |
551 | 0 | << std::endl; |
552 | 0 | last = event.second; |
553 | 0 | } |
554 | 0 | } |
555 | 0 | } |
556 | |
|
557 | 0 | RuntimeProfile::print_child_counters(prefix, ROOT_COUNTER, counter_map, child_counter_map, s); |
558 | | |
559 | | // create copy of _children so we don't need to hold lock while we call |
560 | | // pretty_print() on the children |
561 | 0 | ChildVector children; |
562 | 0 | { |
563 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
564 | 0 | children = _children; |
565 | 0 | } |
566 | |
|
567 | 0 | for (int i = 0; i < children.size(); ++i) { |
568 | 0 | RuntimeProfile* profile = children[i].first; |
569 | 0 | bool indent = children[i].second; |
570 | 0 | profile->pretty_print(s, prefix + (indent ? " " : "")); |
571 | 0 | } |
572 | 0 | } |
573 | | |
574 | 0 | void RuntimeProfile::to_thrift(TRuntimeProfileTree* tree) { |
575 | 0 | tree->nodes.clear(); |
576 | 0 | to_thrift(&tree->nodes); |
577 | 0 | } |
578 | | |
579 | 0 | void RuntimeProfile::to_thrift(std::vector<TRuntimeProfileNode>* nodes) { |
580 | 0 | nodes->reserve(nodes->size() + _children.size()); |
581 | |
|
582 | 0 | int index = nodes->size(); |
583 | 0 | nodes->push_back(TRuntimeProfileNode()); |
584 | 0 | TRuntimeProfileNode& node = (*nodes)[index]; |
585 | 0 | node.name = _name; |
586 | 0 | node.metadata = _metadata; |
587 | 0 | node.timestamp = _timestamp; |
588 | 0 | node.indent = true; |
589 | 0 | if (this->is_set_sink()) { |
590 | 0 | node.__set_is_sink(this->is_sink()); |
591 | 0 | } |
592 | 0 | { |
593 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
594 | 0 | node.child_counters_map = _child_counter_map; |
595 | 0 | for (auto&& [name, counter] : _counter_map) { |
596 | 0 | counter->to_thrift(name, node.counters, node.child_counters_map); |
597 | 0 | } |
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 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
609 | 0 | children = _children; |
610 | 0 | } |
611 | 0 | node.num_children = children.size(); |
612 | |
|
613 | 0 | for (int i = 0; i < children.size(); ++i) { |
614 | 0 | int child_idx = nodes->size(); |
615 | 0 | children[i].first->to_thrift(nodes); |
616 | | // fix up indentation flag |
617 | 0 | (*nodes)[child_idx].indent = children[i].second; |
618 | 0 | } |
619 | 0 | } |
620 | | |
621 | | int64_t RuntimeProfile::units_per_second(const RuntimeProfile::Counter* total_counter, |
622 | 0 | const RuntimeProfile::Counter* timer) { |
623 | 0 | DCHECK(total_counter->type() == TUnit::BYTES || total_counter->type() == TUnit::UNIT); |
624 | 0 | DCHECK(timer->type() == TUnit::TIME_NS); |
625 | |
|
626 | 0 | if (timer->value() == 0) { |
627 | 0 | return 0; |
628 | 0 | } |
629 | | |
630 | 0 | double secs = static_cast<double>(timer->value()) / 1000.0 / 1000.0 / 1000.0; |
631 | 0 | return int64_t(total_counter->value() / secs); |
632 | 0 | } |
633 | | |
634 | 0 | int64_t RuntimeProfile::counter_sum(const std::vector<Counter*>* counters) { |
635 | 0 | int64_t value = 0; |
636 | |
|
637 | 0 | for (int i = 0; i < counters->size(); ++i) { |
638 | 0 | value += (*counters)[i]->value(); |
639 | 0 | } |
640 | |
|
641 | 0 | return value; |
642 | 0 | } |
643 | | |
644 | | RuntimeProfile::Counter* RuntimeProfile::add_rate_counter(const std::string& name, |
645 | 3 | Counter* src_counter) { |
646 | 3 | TUnit::type dst_type; |
647 | | |
648 | 3 | switch (src_counter->type()) { |
649 | 0 | case TUnit::BYTES: |
650 | 0 | dst_type = TUnit::BYTES_PER_SECOND; |
651 | 0 | break; |
652 | | |
653 | 3 | case TUnit::UNIT: |
654 | 3 | dst_type = TUnit::UNIT_PER_SECOND; |
655 | 3 | break; |
656 | | |
657 | 0 | default: |
658 | 0 | DCHECK(false) << "Unsupported src counter type: " << src_counter->type(); |
659 | 0 | return nullptr; |
660 | 3 | } |
661 | | |
662 | 3 | Counter* dst_counter = add_counter(name, dst_type); |
663 | 3 | return dst_counter; |
664 | 3 | } |
665 | | |
666 | | RuntimeProfile::Counter* RuntimeProfile::add_rate_counter(const std::string& name, SampleFn fn, |
667 | 0 | TUnit::type dst_type) { |
668 | 0 | return add_counter(name, dst_type); |
669 | 0 | } |
670 | | |
671 | | RuntimeProfile::Counter* RuntimeProfile::add_sampling_counter(const std::string& name, |
672 | 0 | Counter* src_counter) { |
673 | 0 | DCHECK(src_counter->type() == TUnit::UNIT); |
674 | 0 | return add_counter(name, TUnit::DOUBLE_VALUE); |
675 | 0 | } |
676 | | |
677 | | RuntimeProfile::Counter* RuntimeProfile::add_sampling_counter(const std::string& name, |
678 | 0 | SampleFn sample_fn) { |
679 | 0 | return add_counter(name, TUnit::DOUBLE_VALUE); |
680 | 0 | } |
681 | | |
682 | 0 | RuntimeProfile::EventSequence* RuntimeProfile::add_event_sequence(const std::string& name) { |
683 | 0 | std::lock_guard<std::mutex> l(_event_sequences_lock); |
684 | 0 | EventSequenceMap::iterator timer_it = _event_sequence_map.find(name); |
685 | |
|
686 | 0 | if (timer_it != _event_sequence_map.end()) { |
687 | 0 | return timer_it->second; |
688 | 0 | } |
689 | | |
690 | 0 | EventSequence* timer = _pool->add(new EventSequence()); |
691 | 0 | _event_sequence_map[name] = timer; |
692 | 0 | return timer; |
693 | 0 | } |
694 | | |
695 | | void RuntimeProfile::print_child_counters(const std::string& prefix, |
696 | | const std::string& counter_name, |
697 | | const CounterMap& counter_map, |
698 | | const ChildCounterMap& child_counter_map, |
699 | 0 | std::ostream* s) { |
700 | 0 | std::ostream& stream = *s; |
701 | 0 | ChildCounterMap::const_iterator itr = child_counter_map.find(counter_name); |
702 | |
|
703 | 0 | if (itr != child_counter_map.end()) { |
704 | 0 | const std::set<std::string>& child_counters = itr->second; |
705 | 0 | for (const std::string& child_counter : child_counters) { |
706 | 0 | CounterMap::const_iterator iter = counter_map.find(child_counter); |
707 | 0 | DCHECK(iter != counter_map.end()); |
708 | 0 | stream << prefix << " - " << iter->first << ": " |
709 | 0 | << PrettyPrinter::print(iter->second->value(), iter->second->type()) |
710 | 0 | << std::endl; |
711 | 0 | RuntimeProfile::print_child_counters(prefix + " ", child_counter, counter_map, |
712 | 0 | child_counter_map, s); |
713 | 0 | } |
714 | 0 | } |
715 | 0 | } |
716 | | |
717 | | } // namespace doris |