Coverage Report

Created: 2024-11-21 23:45

/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