Coverage Report

Created: 2025-04-15 11:51

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