be/src/runtime/runtime_profile.cpp
Line | Count | Source |
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 "runtime/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 <memory> |
32 | | #include <string> |
33 | | |
34 | | #include "common/logging.h" |
35 | | #include "common/object_pool.h" |
36 | | #include "runtime/runtime_profile_counter_tree_node.h" |
37 | | #ifdef BE_TEST |
38 | | #include "common/status.h" // For ErrorCode |
39 | | #endif |
40 | | |
41 | | namespace doris { |
42 | | // Thread counters name |
43 | | static const std::string THREAD_VOLUNTARY_CONTEXT_SWITCHES = "VoluntaryContextSwitches"; |
44 | | static const std::string THREAD_INVOLUNTARY_CONTEXT_SWITCHES = "InvoluntaryContextSwitches"; |
45 | | |
46 | | const std::string RuntimeProfile::ROOT_COUNTER; |
47 | | |
48 | 3 | std::unique_ptr<RuntimeProfile> RuntimeProfile::from_thrift(const TRuntimeProfileTree& node) { |
49 | 3 | if (node.nodes.empty()) { |
50 | 0 | return std::make_unique<RuntimeProfile>(""); |
51 | 0 | } |
52 | 3 | TRuntimeProfileNode root_node = node.nodes.front(); |
53 | 3 | std::unique_ptr<RuntimeProfile> res = std::make_unique<RuntimeProfile>(root_node.name); |
54 | 3 | res->update(node); |
55 | 3 | return res; |
56 | 3 | } |
57 | | |
58 | 1.98k | std::unique_ptr<RuntimeProfile> RuntimeProfile::from_proto(const PRuntimeProfileTree& tree) { |
59 | 1.98k | if (tree.nodes().empty()) { |
60 | 0 | return std::make_unique<RuntimeProfile>(""); |
61 | 0 | } |
62 | | |
63 | 1.98k | const PRuntimeProfileNode& root_node = tree.nodes(0); |
64 | 1.98k | std::unique_ptr<RuntimeProfile> res = std::make_unique<RuntimeProfile>(root_node.name()); |
65 | 1.98k | res->update(tree); |
66 | 1.98k | return res; |
67 | 1.98k | } |
68 | | |
69 | | RuntimeProfile::RuntimeProfile(const std::string& name, bool is_averaged_profile) |
70 | 40.6M | : _pool(new ObjectPool()), |
71 | 40.6M | _name(name), |
72 | 40.6M | _metadata(-1), |
73 | 40.6M | _timestamp(-1), |
74 | 40.6M | _is_averaged_profile(is_averaged_profile), |
75 | 40.6M | _counter_total_time(TUnit::TIME_NS, 0, 3), |
76 | 40.6M | _local_time_percent(0) { |
77 | | // TotalTime counter has level3 to disable it from plan profile, because |
78 | | // it contains its child running time, we use exec time instead. |
79 | 40.6M | _counter_map["TotalTime"] = &_counter_total_time; |
80 | 40.6M | } |
81 | | |
82 | 40.8M | RuntimeProfile::~RuntimeProfile() = default; |
83 | | |
84 | 2 | bool RuntimeProfile::Counter::operator==(const Counter& other) const { |
85 | 2 | return _value.load(std::memory_order_relaxed) == other._value.load(std::memory_order_relaxed) && |
86 | 2 | _type == other._type && _level == other._level; |
87 | 2 | } |
88 | | |
89 | 19.4k | void RuntimeProfile::merge(const RuntimeProfile* other) { |
90 | 19.4k | DCHECK(other != nullptr); |
91 | | |
92 | | // Merge this level |
93 | 19.4k | { |
94 | 19.4k | CounterMap::iterator dst_iter; |
95 | 19.4k | CounterMap::const_iterator src_iter; |
96 | 19.4k | std::lock_guard<std::mutex> l(_counter_map_lock); |
97 | 19.4k | std::lock_guard<std::mutex> m(other->_counter_map_lock); |
98 | | |
99 | 71.4k | for (src_iter = other->_counter_map.begin(); src_iter != other->_counter_map.end(); |
100 | 51.9k | ++src_iter) { |
101 | 51.9k | dst_iter = _counter_map.find(src_iter->first); |
102 | | |
103 | 51.9k | if (dst_iter == _counter_map.end()) { |
104 | 32.5k | _counter_map[src_iter->first] = _pool->add(src_iter->second->clone()); |
105 | 32.5k | } else { |
106 | 19.4k | DCHECK(dst_iter->second->type() == src_iter->second->type()); |
107 | | |
108 | 19.4k | if (dst_iter->second->type() == TUnit::DOUBLE_VALUE) { |
109 | 0 | double new_val = |
110 | 0 | dst_iter->second->double_value() + src_iter->second->double_value(); |
111 | 0 | dst_iter->second->set(new_val); |
112 | 19.4k | } else { |
113 | 19.4k | dst_iter->second->update(src_iter->second->value()); |
114 | 19.4k | } |
115 | 19.4k | } |
116 | 51.9k | } |
117 | | |
118 | 19.4k | ChildCounterMap::const_iterator child_counter_src_itr; |
119 | | |
120 | 19.4k | for (child_counter_src_itr = other->_child_counter_map.begin(); |
121 | 38.8k | child_counter_src_itr != other->_child_counter_map.end(); ++child_counter_src_itr) { |
122 | 19.4k | _child_counter_map[child_counter_src_itr->first].insert( |
123 | 19.4k | child_counter_src_itr->second.begin(), child_counter_src_itr->second.end()); |
124 | 19.4k | } |
125 | 19.4k | } |
126 | | |
127 | 19.4k | { |
128 | 19.4k | std::lock_guard<std::mutex> l(_children_lock); |
129 | 19.4k | std::lock_guard<std::mutex> m(other->_children_lock); |
130 | | |
131 | | // Recursively merge children with matching names |
132 | 19.4k | for (int i = 0; i < other->_children.size(); ++i) { |
133 | 16 | RuntimeProfile* other_child = other->_children[i].first; |
134 | 16 | ChildMap::iterator j = _child_map.find(other_child->_name); |
135 | 16 | RuntimeProfile* child = nullptr; |
136 | | |
137 | 16 | if (j != _child_map.end()) { |
138 | 10 | child = j->second; |
139 | 10 | } else { |
140 | 6 | child = _pool->add(new RuntimeProfile(other_child->_name)); |
141 | 6 | child->_local_time_percent = other_child->_local_time_percent; |
142 | 6 | child->_metadata = other_child->_metadata; |
143 | 6 | child->_timestamp = other_child->_timestamp; |
144 | 6 | bool indent_other_child = other->_children[i].second; |
145 | 6 | _child_map[child->_name] = child; |
146 | 6 | _children.push_back(std::make_pair(child, indent_other_child)); |
147 | 6 | } |
148 | | |
149 | 16 | child->merge(other_child); |
150 | 16 | } |
151 | 19.4k | } |
152 | 19.4k | } |
153 | | |
154 | 10.0k | void RuntimeProfile::update(const TRuntimeProfileTree& thrift_profile) { |
155 | 10.0k | int idx = 0; |
156 | 10.0k | update(thrift_profile.nodes, &idx); |
157 | 10.0k | DCHECK_EQ(idx, thrift_profile.nodes.size()); |
158 | 10.0k | } |
159 | | |
160 | 1.98k | void RuntimeProfile::update(const PRuntimeProfileTree& proto_profile) { |
161 | 1.98k | int idx = 0; |
162 | 1.98k | update(proto_profile.nodes(), &idx); |
163 | 1.98k | DCHECK_EQ(idx, proto_profile.nodes_size()); |
164 | 1.98k | } |
165 | | |
166 | 10.9k | void RuntimeProfile::update(const std::vector<TRuntimeProfileNode>& nodes, int* idx) { |
167 | 10.9k | DCHECK_LT(*idx, nodes.size()); |
168 | 10.9k | const TRuntimeProfileNode& node = nodes[*idx]; |
169 | 10.9k | { |
170 | 10.9k | std::lock_guard<std::mutex> l(_counter_map_lock); |
171 | | // update this level |
172 | 10.9k | std::map<std::string, Counter*>::iterator dst_iter; |
173 | | |
174 | 13.6k | for (int i = 0; i < node.counters.size(); ++i) { |
175 | 2.73k | const TCounter& tcounter = node.counters[i]; |
176 | 2.73k | CounterMap::iterator j = _counter_map.find(tcounter.name); |
177 | | |
178 | 2.73k | if (j == _counter_map.end()) { |
179 | 2.65k | _counter_map[tcounter.name] = |
180 | 2.65k | _pool->add(new Counter(tcounter.type, tcounter.value)); |
181 | 2.65k | } else { |
182 | 78 | if (j->second->type() != tcounter.type) { |
183 | 0 | LOG(ERROR) << "Cannot update counters with the same name (" << j->first |
184 | 0 | << ") but different types."; |
185 | 78 | } else { |
186 | 78 | j->second->set(tcounter.value); |
187 | 78 | } |
188 | 78 | } |
189 | 2.73k | } |
190 | | |
191 | 10.9k | ChildCounterMap::const_iterator child_counter_src_itr; |
192 | | |
193 | 10.9k | for (child_counter_src_itr = node.child_counters_map.begin(); |
194 | 11.4k | child_counter_src_itr != node.child_counters_map.end(); ++child_counter_src_itr) { |
195 | 498 | _child_counter_map[child_counter_src_itr->first].insert( |
196 | 498 | child_counter_src_itr->second.begin(), child_counter_src_itr->second.end()); |
197 | 498 | } |
198 | 10.9k | } |
199 | | |
200 | 10.9k | { |
201 | 10.9k | std::lock_guard<std::mutex> l(_info_strings_lock); |
202 | 10.9k | const InfoStrings& info_strings = node.info_strings; |
203 | 10.9k | for (const std::string& key : node.info_strings_display_order) { |
204 | | // Look for existing info strings and update in place. If there |
205 | | // are new strings, add them to the end of the display order. |
206 | | // TODO: Is nodes.info_strings always a superset of |
207 | | // _info_strings? If so, can just copy the display order. |
208 | 16 | InfoStrings::const_iterator it = info_strings.find(key); |
209 | 16 | DCHECK(it != info_strings.end()); |
210 | 16 | InfoStrings::iterator existing = _info_strings.find(key); |
211 | | |
212 | 16 | if (existing == _info_strings.end()) { |
213 | 12 | _info_strings.insert(std::make_pair(key, it->second)); |
214 | 12 | _info_strings_display_order.push_back(key); |
215 | 12 | } else { |
216 | 4 | _info_strings[key] = it->second; |
217 | 4 | } |
218 | 16 | } |
219 | 10.9k | } |
220 | | |
221 | 10.9k | ++*idx; |
222 | 10.9k | { |
223 | 10.9k | std::lock_guard<std::mutex> l(_children_lock); |
224 | | |
225 | | // update children with matching names; create new ones if they don't match |
226 | 11.7k | for (int i = 0; i < node.num_children; ++i) { |
227 | 836 | const TRuntimeProfileNode& tchild = nodes[*idx]; |
228 | 836 | ChildMap::iterator j = _child_map.find(tchild.name); |
229 | 836 | RuntimeProfile* child = nullptr; |
230 | | |
231 | 836 | if (j != _child_map.end()) { |
232 | 66 | child = j->second; |
233 | 770 | } else { |
234 | 770 | child = _pool->add(new RuntimeProfile(tchild.name)); |
235 | 770 | child->_metadata = tchild.metadata; |
236 | 770 | child->_timestamp = tchild.timestamp; |
237 | 770 | _child_map[tchild.name] = child; |
238 | 770 | _children.push_back(std::make_pair(child, tchild.indent)); |
239 | 770 | } |
240 | | |
241 | 836 | child->update(nodes, idx); |
242 | 836 | } |
243 | 10.9k | } |
244 | 10.9k | } |
245 | | |
246 | | void RuntimeProfile::update(const google::protobuf::RepeatedPtrField<PRuntimeProfileNode>& nodes, |
247 | 1.99k | int* idx) { |
248 | 1.99k | DCHECK_LT(*idx, nodes.size()); |
249 | 1.99k | const PRuntimeProfileNode& node = nodes.Get(*idx); |
250 | | |
251 | 1.99k | { |
252 | 1.99k | std::lock_guard<std::mutex> l(_counter_map_lock); |
253 | | |
254 | 1.99k | for (const auto& pcounter : node.counters()) { |
255 | 20 | const std::string& name = pcounter.name(); |
256 | 20 | auto j = _counter_map.find(name); |
257 | | |
258 | 20 | if (j == _counter_map.end()) { |
259 | 14 | _counter_map[name] = |
260 | 14 | _pool->add(new Counter(unit_to_thrift(pcounter.type()), pcounter.value())); |
261 | 14 | } else { |
262 | 6 | if (unit_to_proto(j->second->type()) != pcounter.type()) { |
263 | 0 | LOG(ERROR) << "Cannot update counters with the same name (" << name |
264 | 0 | << ") but different types."; |
265 | 6 | } else { |
266 | 6 | j->second->set(pcounter.value()); |
267 | 6 | } |
268 | 6 | } |
269 | 20 | } |
270 | | |
271 | 1.99k | for (const auto& kv : node.child_counters_map()) { |
272 | 20 | for (const auto& child_name : kv.second.child_counters()) { |
273 | 20 | _child_counter_map[kv.first].insert(child_name); |
274 | 20 | } |
275 | 14 | } |
276 | 1.99k | } |
277 | | |
278 | 1.99k | { |
279 | 1.99k | std::lock_guard<std::mutex> l(_info_strings_lock); |
280 | 1.99k | const auto& info_map = node.info_strings(); |
281 | | |
282 | 11.8k | for (const std::string& key : node.info_strings_display_order()) { |
283 | 11.8k | auto it = info_map.find(key); |
284 | 11.8k | DCHECK(it != info_map.end()); |
285 | | |
286 | 11.8k | auto existing = _info_strings.find(key); |
287 | 11.8k | if (existing == _info_strings.end()) { |
288 | 11.8k | _info_strings.insert(std::make_pair(key, it->second)); |
289 | 11.8k | _info_strings_display_order.push_back(key); |
290 | 11.8k | } else { |
291 | 1 | _info_strings[key] = it->second; |
292 | 1 | } |
293 | 11.8k | } |
294 | 1.99k | } |
295 | | |
296 | 1.99k | ++*idx; |
297 | | |
298 | 1.99k | { |
299 | 1.99k | std::lock_guard<std::mutex> l(_children_lock); |
300 | 2.01k | for (int i = 0; i < node.num_children(); ++i) { |
301 | 12 | const PRuntimeProfileNode& pchild = nodes.Get(*idx); |
302 | 12 | RuntimeProfile* child = nullptr; |
303 | | |
304 | 12 | auto j = _child_map.find(pchild.name()); |
305 | 12 | if (j != _child_map.end()) { |
306 | 5 | child = j->second; |
307 | 7 | } else { |
308 | 7 | child = _pool->add(new RuntimeProfile(pchild.name())); |
309 | 7 | child->_metadata = pchild.metadata(); |
310 | 7 | child->_timestamp = pchild.timestamp(); |
311 | 7 | _child_map[pchild.name()] = child; |
312 | 7 | _children.emplace_back(child, pchild.indent()); |
313 | 7 | } |
314 | | |
315 | 12 | child->update(nodes, idx); |
316 | 12 | } |
317 | 1.99k | } |
318 | 1.99k | } |
319 | | |
320 | 0 | void RuntimeProfile::divide(int n) { |
321 | 0 | DCHECK_GT(n, 0); |
322 | 0 | std::map<std::string, Counter*>::iterator iter; |
323 | 0 | { |
324 | 0 | std::lock_guard<std::mutex> l(_counter_map_lock); |
325 | |
|
326 | 0 | for (iter = _counter_map.begin(); iter != _counter_map.end(); ++iter) { |
327 | 0 | if (iter->second->type() == TUnit::DOUBLE_VALUE) { |
328 | 0 | iter->second->set(iter->second->double_value() / n); |
329 | 0 | } else { |
330 | 0 | int64_t value = iter->second->_value.load(); |
331 | 0 | value = value / n; |
332 | 0 | iter->second->_value.store(value); |
333 | 0 | } |
334 | 0 | } |
335 | 0 | } |
336 | 0 | { |
337 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
338 | |
|
339 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
340 | 0 | i->second->divide(n); |
341 | 0 | } |
342 | 0 | } |
343 | 0 | } |
344 | | |
345 | 0 | void RuntimeProfile::clear_children() { |
346 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
347 | 0 | _children.clear(); |
348 | 0 | } |
349 | | |
350 | 0 | void RuntimeProfile::compute_time_in_profile() { |
351 | 0 | compute_time_in_profile(total_time_counter()->value()); |
352 | 0 | } |
353 | | |
354 | 0 | void RuntimeProfile::compute_time_in_profile(int64_t total) { |
355 | 0 | if (total == 0) { |
356 | 0 | return; |
357 | 0 | } |
358 | | |
359 | | // Add all the total times in all the children |
360 | 0 | int64_t total_child_time = 0; |
361 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
362 | |
|
363 | 0 | for (int i = 0; i < _children.size(); ++i) { |
364 | 0 | total_child_time += _children[i].first->total_time_counter()->value(); |
365 | 0 | } |
366 | |
|
367 | 0 | int64_t local_time = total_time_counter()->value() - total_child_time; |
368 | | // Counters have some margin, set to 0 if it was negative. |
369 | 0 | local_time = std::max<int64_t>(0L, local_time); |
370 | 0 | _local_time_percent = static_cast<double>(local_time) / static_cast<double>(total); |
371 | 0 | _local_time_percent = std::min(1.0, _local_time_percent) * 100; |
372 | | |
373 | | // Recurse on children |
374 | 0 | for (int i = 0; i < _children.size(); ++i) { |
375 | 0 | _children[i].first->compute_time_in_profile(total); |
376 | 0 | } |
377 | 0 | } |
378 | | |
379 | 9.64M | RuntimeProfile* RuntimeProfile::create_child(const std::string& name, bool indent, bool prepend) { |
380 | 9.64M | std::lock_guard<std::mutex> l(_children_lock); |
381 | 18.4E | DCHECK(_child_map.find(name) == _child_map.end()) << ", name: " << name; |
382 | 9.64M | RuntimeProfile* child = _pool->add(new RuntimeProfile(name)); |
383 | 9.64M | if (this->is_set_metadata()) { |
384 | 10.3k | child->set_metadata(this->metadata()); |
385 | 10.3k | } |
386 | | |
387 | 9.64M | if (_children.empty()) { |
388 | 285k | add_child_unlock(child, indent, nullptr); |
389 | 9.35M | } else { |
390 | 9.35M | auto* pos = prepend ? _children.begin()->first : nullptr; |
391 | 9.35M | add_child_unlock(child, indent, pos); |
392 | 9.35M | } |
393 | 9.64M | return child; |
394 | 9.64M | } |
395 | | |
396 | 26.6M | void RuntimeProfile::add_child_unlock(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
397 | 26.6M | DCHECK(child != nullptr); |
398 | 26.6M | _child_map[child->_name] = child; |
399 | | |
400 | 26.6M | if (loc == nullptr) { |
401 | 26.1M | _children.push_back(std::make_pair(child, indent)); |
402 | 26.1M | } else { |
403 | 18.4E | for (ChildVector::iterator it = _children.begin(); it != _children.end(); ++it) { |
404 | 553k | if (it->first == loc) { |
405 | 553k | _children.insert(it, std::make_pair(child, indent)); |
406 | 553k | return; |
407 | 553k | } |
408 | 553k | } |
409 | 18.4E | DCHECK(false) << "Invalid loc"; |
410 | 18.4E | } |
411 | 26.6M | } |
412 | | |
413 | 17.0M | void RuntimeProfile::add_child(RuntimeProfile* child, bool indent, RuntimeProfile* loc) { |
414 | 17.0M | std::lock_guard<std::mutex> l(_children_lock); |
415 | 17.0M | add_child_unlock(child, indent, loc); |
416 | 17.0M | } |
417 | | |
418 | 148k | RuntimeProfile* RuntimeProfile::get_child(std::string name) { |
419 | 148k | std::lock_guard<std::mutex> l(_children_lock); |
420 | 148k | auto it = _child_map.find(name); |
421 | | |
422 | 148k | if (it == _child_map.end()) { |
423 | 2 | return nullptr; |
424 | 2 | } |
425 | | |
426 | 148k | return it->second; |
427 | 148k | } |
428 | | |
429 | 4 | void RuntimeProfile::get_children(std::vector<RuntimeProfile*>* children) const { |
430 | 4 | children->clear(); |
431 | 4 | std::lock_guard<std::mutex> l(_children_lock); |
432 | | |
433 | 16 | for (ChildMap::const_iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
434 | 12 | children->push_back(i->second); |
435 | 12 | } |
436 | 4 | } |
437 | | |
438 | 0 | void RuntimeProfile::get_all_children(std::vector<RuntimeProfile*>* children) { |
439 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
440 | |
|
441 | 0 | for (ChildMap::iterator i = _child_map.begin(); i != _child_map.end(); ++i) { |
442 | 0 | children->push_back(i->second); |
443 | 0 | i->second->get_all_children(children); |
444 | 0 | } |
445 | 0 | } |
446 | | |
447 | 52.0M | void RuntimeProfile::add_info_string(const std::string& key, const std::string& value) { |
448 | 52.0M | std::lock_guard<std::mutex> l(_info_strings_lock); |
449 | 52.0M | InfoStrings::iterator it = _info_strings.find(key); |
450 | | |
451 | 52.0M | if (it == _info_strings.end()) { |
452 | 23.1M | _info_strings.insert(std::make_pair(key, value)); |
453 | 23.1M | _info_strings_display_order.push_back(key); |
454 | 28.8M | } else { |
455 | 28.8M | it->second = value; |
456 | 28.8M | } |
457 | 52.0M | } |
458 | | |
459 | 11.9k | const std::string* RuntimeProfile::get_info_string(const std::string& key) { |
460 | 11.9k | std::lock_guard<std::mutex> l(_info_strings_lock); |
461 | 11.9k | InfoStrings::const_iterator it = _info_strings.find(key); |
462 | | |
463 | 11.9k | if (it == _info_strings.end()) { |
464 | 2 | return nullptr; |
465 | 2 | } |
466 | | |
467 | 11.9k | return &it->second; |
468 | 11.9k | } |
469 | | |
470 | | RuntimeProfile::HighWaterMarkCounter* RuntimeProfile::AddHighWaterMarkCounter( |
471 | | const std::string& name, TUnit::type unit, const std::string& parent_counter_name, |
472 | 14.1M | int64_t level) { |
473 | 14.1M | DCHECK_EQ(_is_averaged_profile, false); |
474 | 14.1M | std::lock_guard<std::mutex> l(_counter_map_lock); |
475 | 14.1M | if (_counter_map.find(name) != _counter_map.end()) { |
476 | 83 | return reinterpret_cast<RuntimeProfile::HighWaterMarkCounter*>(_counter_map[name]); |
477 | 83 | } |
478 | 14.1M | DCHECK(parent_counter_name == ROOT_COUNTER || |
479 | 14.1M | _counter_map.find(parent_counter_name) != _counter_map.end()); |
480 | 14.1M | RuntimeProfile::HighWaterMarkCounter* counter = |
481 | 14.1M | _pool->add(new RuntimeProfile::HighWaterMarkCounter(unit, level, parent_counter_name)); |
482 | 14.1M | _counter_map[name] = counter; |
483 | 14.1M | _child_counter_map[parent_counter_name].insert(name); |
484 | 14.1M | return counter; |
485 | 14.1M | } |
486 | | |
487 | | RuntimeProfile::Counter* RuntimeProfile::add_counter(const std::string& name, TUnit::type type, |
488 | | const std::string& parent_counter_name, |
489 | 208M | int64_t level) { |
490 | 208M | std::lock_guard<std::mutex> l(_counter_map_lock); |
491 | | |
492 | 208M | if (_counter_map.find(name) != _counter_map.end()) { |
493 | 24.2M | return _counter_map[name]; |
494 | 24.2M | } |
495 | | |
496 | | // Parent counter must already exist. |
497 | 208M | DCHECK(parent_counter_name == ROOT_COUNTER || |
498 | 184M | _counter_map.find(parent_counter_name) != _counter_map.end()); |
499 | | |
500 | 184M | Counter* counter = _pool->add(new Counter(type, 0, level)); |
501 | 184M | _counter_map[name] = counter; |
502 | 184M | _child_counter_map[parent_counter_name].insert(name); |
503 | 184M | return counter; |
504 | 208M | } |
505 | | |
506 | | RuntimeProfile::NonZeroCounter* RuntimeProfile::add_nonzero_counter( |
507 | | const std::string& name, TUnit::type type, const std::string& parent_counter_name, |
508 | 2.67M | int64_t level) { |
509 | 2.67M | std::lock_guard<std::mutex> l(_counter_map_lock); |
510 | 2.67M | if (_counter_map.find(name) != _counter_map.end()) { |
511 | 0 | DCHECK(dynamic_cast<NonZeroCounter*>(_counter_map[name])); |
512 | 0 | return static_cast<NonZeroCounter*>(_counter_map[name]); |
513 | 0 | } |
514 | | |
515 | 2.67M | DCHECK(parent_counter_name == ROOT_COUNTER || |
516 | 2.67M | _counter_map.find(parent_counter_name) != _counter_map.end()); |
517 | 2.67M | NonZeroCounter* counter = _pool->add(new NonZeroCounter(type, level, parent_counter_name)); |
518 | 2.67M | _counter_map[name] = counter; |
519 | 2.67M | _child_counter_map[parent_counter_name].insert(name); |
520 | 2.67M | return counter; |
521 | 2.67M | } |
522 | | |
523 | | RuntimeProfile::DerivedCounter* RuntimeProfile::add_derived_counter( |
524 | | const std::string& name, TUnit::type type, const DerivedCounterFunction& counter_fn, |
525 | 678k | const std::string& parent_counter_name) { |
526 | 678k | std::lock_guard<std::mutex> l(_counter_map_lock); |
527 | | |
528 | 678k | if (_counter_map.find(name) != _counter_map.end()) { |
529 | 0 | return nullptr; |
530 | 0 | } |
531 | | |
532 | 678k | DerivedCounter* counter = _pool->add(new DerivedCounter(type, counter_fn)); |
533 | 678k | _counter_map[name] = counter; |
534 | 678k | _child_counter_map[parent_counter_name].insert(name); |
535 | 678k | return counter; |
536 | 678k | } |
537 | | |
538 | | void RuntimeProfile::add_description(const std::string& name, const std::string& description, |
539 | 201k | std::string parent_counter_name) { |
540 | 201k | std::lock_guard<std::mutex> l(_counter_map_lock); |
541 | | |
542 | 201k | if (_counter_map.find(name) != _counter_map.end()) { |
543 | 0 | Counter* counter = _counter_map[name]; |
544 | 0 | if (dynamic_cast<DescriptionEntry*>(counter) != nullptr) { |
545 | | // Do replace instead of update to avoid data race. |
546 | 0 | _counter_map.erase(name); |
547 | 0 | } else { |
548 | 0 | DCHECK(false) << "Counter type mismatch, name: " << name |
549 | 0 | << ", type: " << counter->type() << ", description: " << description; |
550 | 0 | } |
551 | 0 | } |
552 | | |
553 | | // Parent counter must already exist. |
554 | 201k | DCHECK(parent_counter_name == ROOT_COUNTER || |
555 | 201k | _counter_map.find(parent_counter_name) != _counter_map.end()); |
556 | 201k | DescriptionEntry* counter = _pool->add(new DescriptionEntry(name, description)); |
557 | 201k | _counter_map[name] = counter; |
558 | 201k | _child_counter_map[parent_counter_name].insert(name); |
559 | 201k | } |
560 | | |
561 | | RuntimeProfile::ConditionCounter* RuntimeProfile::add_conditition_counter( |
562 | | const std::string& name, TUnit::type type, const ConditionCounterFunction& counter_fn, |
563 | 5.67k | const std::string& parent_counter_name, int64_t level) { |
564 | 5.67k | std::lock_guard<std::mutex> l(_counter_map_lock); |
565 | | |
566 | 5.67k | if (_counter_map.find(name) != _counter_map.end()) { |
567 | 1.45k | RuntimeProfile::ConditionCounter* contition_counter = |
568 | 1.45k | dynamic_cast<ConditionCounter*>(_counter_map[name]); |
569 | 1.45k | if (contition_counter == nullptr) { |
570 | 0 | throw doris::Exception(doris::ErrorCode::INTERNAL_ERROR, |
571 | 0 | "Failed to add a conditition counter that is duplicate and of a " |
572 | 0 | "different type for {}.", |
573 | 0 | name); |
574 | 0 | } |
575 | 1.45k | return contition_counter; |
576 | 1.45k | } |
577 | | |
578 | 4.22k | ConditionCounter* counter = _pool->add(new ConditionCounter(type, counter_fn, level)); |
579 | 4.22k | _counter_map[name] = counter; |
580 | 4.22k | _child_counter_map[parent_counter_name].insert(name); |
581 | 4.22k | return counter; |
582 | 5.67k | } |
583 | | |
584 | 402k | RuntimeProfile::Counter* RuntimeProfile::get_counter(const std::string& name) { |
585 | 402k | std::lock_guard<std::mutex> l(_counter_map_lock); |
586 | | |
587 | 402k | if (_counter_map.find(name) != _counter_map.end()) { |
588 | 99.4k | return _counter_map[name]; |
589 | 99.4k | } |
590 | | |
591 | 302k | return nullptr; |
592 | 402k | } |
593 | | |
594 | 0 | void RuntimeProfile::get_counters(const std::string& name, std::vector<Counter*>* counters) { |
595 | 0 | Counter* c = get_counter(name); |
596 | |
|
597 | 0 | if (c != nullptr) { |
598 | 0 | counters->push_back(c); |
599 | 0 | } |
600 | |
|
601 | 0 | std::lock_guard<std::mutex> l(_children_lock); |
602 | |
|
603 | 0 | for (int i = 0; i < _children.size(); ++i) { |
604 | 0 | _children[i].first->get_counters(name, counters); |
605 | 0 | } |
606 | 0 | } |
607 | | |
608 | | // Print the profile: |
609 | | // 1. Profile Name |
610 | | // 2. Info Strings |
611 | | // 3. Counters |
612 | | // 4. Children |
613 | | void RuntimeProfile::pretty_print(std::ostream* s, const std::string& prefix, |
614 | 234 | int64_t profile_level) const { |
615 | 234 | std::ostream& stream = *s; |
616 | | |
617 | | // create copy of _counter_map and _child_counter_map so we don't need to hold lock |
618 | | // while we call value() on the counters |
619 | 234 | CounterMap counter_map; |
620 | 234 | ChildCounterMap child_counter_map; |
621 | 234 | { |
622 | 234 | std::lock_guard<std::mutex> l(_counter_map_lock); |
623 | 234 | counter_map = _counter_map; |
624 | 234 | child_counter_map = _child_counter_map; |
625 | 234 | } |
626 | | |
627 | 234 | std::map<std::string, Counter*>::const_iterator total_time = counter_map.find("TotalTime"); |
628 | 234 | DCHECK(total_time != counter_map.end()); |
629 | | |
630 | 234 | stream.flags(std::ios::fixed); |
631 | 234 | stream << prefix << _name << ":"; |
632 | | |
633 | 234 | if (total_time->second->value() != 0) { |
634 | 0 | stream << "(Active: " |
635 | 0 | << PrettyPrinter::print(total_time->second->value(), total_time->second->type()) |
636 | 0 | << ", non-child: " << std::setprecision(2) << _local_time_percent << "%)"; |
637 | 0 | } |
638 | | |
639 | 234 | stream << std::endl; |
640 | | |
641 | 234 | { |
642 | 234 | std::lock_guard<std::mutex> l(_info_strings_lock); |
643 | 234 | for (const std::string& key : _info_strings_display_order) { |
644 | 1 | stream << prefix << " - " << key << ": " << _info_strings.find(key)->second |
645 | 1 | << std::endl; |
646 | 1 | } |
647 | 234 | } |
648 | | |
649 | | // Build counter tree and prune by profile_level before printing |
650 | 234 | RuntimeProfileCounterTreeNode counter_tree = |
651 | 234 | RuntimeProfileCounterTreeNode::from_map(counter_map, child_counter_map, ROOT_COUNTER); |
652 | 234 | counter_tree = RuntimeProfileCounterTreeNode::prune_the_tree(counter_tree, profile_level); |
653 | 234 | counter_tree.pretty_print(s, prefix); |
654 | | |
655 | | // create copy of _children so we don't need to hold lock while we call |
656 | | // pretty_print() on the children |
657 | 234 | ChildVector children; |
658 | 234 | { |
659 | 234 | std::lock_guard<std::mutex> l(_children_lock); |
660 | 234 | children = _children; |
661 | 234 | } |
662 | | |
663 | 320 | for (int i = 0; i < children.size(); ++i) { |
664 | 86 | RuntimeProfile* profile = children[i].first; |
665 | 86 | bool indent = children[i].second; |
666 | 86 | profile->pretty_print(s, prefix + (indent ? " " : "")); |
667 | 86 | } |
668 | 234 | } |
669 | | |
670 | 18.7k | void RuntimeProfile::to_thrift(TRuntimeProfileTree* tree, int64_t profile_level) { |
671 | 18.7k | tree->nodes.clear(); |
672 | 18.7k | to_thrift(&tree->nodes, profile_level); |
673 | 18.7k | } |
674 | | |
675 | 95.5k | void RuntimeProfile::to_thrift(std::vector<TRuntimeProfileNode>* nodes, int64_t profile_level) { |
676 | 95.5k | size_t index = nodes->size(); |
677 | 95.5k | nodes->push_back(TRuntimeProfileNode()); |
678 | 95.5k | TRuntimeProfileNode& node = (*nodes)[index]; |
679 | 95.5k | node.name = _name; |
680 | 95.5k | node.metadata = _metadata; |
681 | 95.5k | node.timestamp = _timestamp; |
682 | 95.5k | node.indent = true; |
683 | | |
684 | 95.5k | { |
685 | 95.5k | std::lock_guard<std::mutex> l(_counter_map_lock); |
686 | 95.5k | RuntimeProfileCounterTreeNode conter_tree = RuntimeProfileCounterTreeNode::from_map( |
687 | 95.5k | _counter_map, _child_counter_map, ROOT_COUNTER); |
688 | 95.5k | conter_tree = RuntimeProfileCounterTreeNode::prune_the_tree(conter_tree, profile_level); |
689 | 95.5k | conter_tree.to_thrift(node.counters, node.child_counters_map); |
690 | 95.5k | } |
691 | | |
692 | 95.5k | { |
693 | 95.5k | std::lock_guard<std::mutex> l(_info_strings_lock); |
694 | 95.5k | node.info_strings = _info_strings; |
695 | 95.5k | node.info_strings_display_order = _info_strings_display_order; |
696 | 95.5k | } |
697 | | |
698 | 95.5k | ChildVector children; |
699 | 95.5k | { |
700 | | // _children may be modified during to_thrift(), |
701 | | // so we have to lock and copy _children to avoid race condition |
702 | 95.5k | std::lock_guard<std::mutex> l(_children_lock); |
703 | 95.5k | children = _children; |
704 | 95.5k | } |
705 | 95.5k | node.num_children = cast_set<int32_t>(children.size()); |
706 | 95.5k | nodes->reserve(nodes->size() + children.size()); |
707 | | |
708 | 172k | for (int i = 0; i < children.size(); ++i) { |
709 | 76.8k | size_t child_idx = nodes->size(); |
710 | 76.8k | children[i].first->to_thrift(nodes, profile_level); |
711 | | // fix up indentation flag |
712 | 76.8k | (*nodes)[child_idx].indent = children[i].second; |
713 | 76.8k | } |
714 | 95.5k | } |
715 | | |
716 | 1.98k | void RuntimeProfile::to_proto(PRuntimeProfileTree* tree, int64_t profile_level) { |
717 | 1.98k | tree->clear_nodes(); |
718 | 1.98k | to_proto(tree->mutable_nodes(), profile_level); |
719 | 1.98k | } |
720 | | |
721 | | void RuntimeProfile::to_proto(google::protobuf::RepeatedPtrField<PRuntimeProfileNode>* nodes, |
722 | 1.98k | int64_t profile_level) { |
723 | 1.98k | PRuntimeProfileNode* node = nodes->Add(); // allocate new node |
724 | 1.98k | node->set_name(_name); |
725 | 1.98k | node->set_metadata(_metadata); |
726 | 1.98k | node->set_timestamp(_timestamp); |
727 | 1.98k | node->set_indent(true); |
728 | | |
729 | 1.98k | { |
730 | 1.98k | std::lock_guard<std::mutex> l(_counter_map_lock); |
731 | 1.98k | RuntimeProfileCounterTreeNode counter_tree = RuntimeProfileCounterTreeNode::from_map( |
732 | 1.98k | _counter_map, _child_counter_map, ROOT_COUNTER); |
733 | 1.98k | counter_tree = RuntimeProfileCounterTreeNode::prune_the_tree(counter_tree, profile_level); |
734 | 1.98k | counter_tree.to_proto(node->mutable_counters(), node->mutable_child_counters_map()); |
735 | 1.98k | } |
736 | | |
737 | 1.98k | { |
738 | 1.98k | std::lock_guard<std::mutex> l(_info_strings_lock); |
739 | 1.98k | auto* info_map = node->mutable_info_strings(); |
740 | 11.8k | for (const auto& kv : _info_strings) { |
741 | 11.8k | (*info_map)[kv.first] = kv.second; |
742 | 11.8k | } |
743 | 11.8k | for (const auto& key : _info_strings_display_order) { |
744 | 11.8k | node->add_info_strings_display_order(key); |
745 | 11.8k | } |
746 | 1.98k | } |
747 | | |
748 | 1.98k | ChildVector children; |
749 | 1.98k | { |
750 | 1.98k | std::lock_guard<std::mutex> l(_children_lock); |
751 | 1.98k | children = _children; |
752 | 1.98k | } |
753 | | |
754 | 1.98k | node->set_num_children(cast_set<int32_t>(children.size())); |
755 | | |
756 | 1.98k | for (const auto& child : children) { |
757 | 6 | int child_index = cast_set<int>(nodes->size()); // capture index for indent correction |
758 | 6 | child.first->to_proto(nodes, profile_level); |
759 | 6 | (*nodes)[child_index].set_indent(child.second); |
760 | 6 | } |
761 | 1.98k | } |
762 | | |
763 | | int64_t RuntimeProfile::units_per_second(const RuntimeProfile::Counter* total_counter, |
764 | 3.87k | const RuntimeProfile::Counter* timer) { |
765 | 3.87k | DCHECK(total_counter->type() == TUnit::BYTES || total_counter->type() == TUnit::UNIT); |
766 | 3.87k | DCHECK(timer->type() == TUnit::TIME_NS); |
767 | | |
768 | 3.87k | if (timer->value() == 0) { |
769 | 3.87k | return 0; |
770 | 3.87k | } |
771 | | |
772 | 3 | double secs = static_cast<double>(timer->value()) / 1000.0 / 1000.0 / 1000.0; |
773 | 3 | return int64_t(static_cast<double>(total_counter->value()) / secs); |
774 | 3.87k | } |
775 | | |
776 | 0 | int64_t RuntimeProfile::counter_sum(const std::vector<Counter*>* counters) { |
777 | 0 | int64_t value = 0; |
778 | |
|
779 | 0 | for (int i = 0; i < counters->size(); ++i) { |
780 | 0 | value += (*counters)[i]->value(); |
781 | 0 | } |
782 | |
|
783 | 0 | return value; |
784 | 0 | } |
785 | | |
786 | | void RuntimeProfile::print_child_counters(const std::string& prefix, |
787 | | const std::string& counter_name, |
788 | | const CounterMap& counter_map, |
789 | | const ChildCounterMap& child_counter_map, |
790 | 0 | std::ostream* s) { |
791 | 0 | auto itr = child_counter_map.find(counter_name); |
792 | |
|
793 | 0 | if (itr != child_counter_map.end()) { |
794 | 0 | const std::set<std::string>& child_counters = itr->second; |
795 | 0 | for (const std::string& child_counter : child_counters) { |
796 | 0 | auto iter = counter_map.find(child_counter); |
797 | | DCHECK(iter != counter_map.end()); |
798 | 0 | iter->second->pretty_print(s, prefix, iter->first); |
799 | 0 | RuntimeProfile::print_child_counters(prefix + " ", child_counter, counter_map, |
800 | 0 | child_counter_map, s); |
801 | 0 | } |
802 | 0 | } |
803 | 0 | } |
804 | | |
805 | | } // namespace doris |