1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
|
// Copyright Vespa.ai. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
#include "execution_profiler.h"
#include <vespa/vespalib/stllike/hash_map.h>
#include <vespa/vespalib/stllike/hash_map.hpp>
#include <vespa/vespalib/data/slime/slime.h>
#include <cassert>
namespace vespalib {
struct ExecutionProfiler::ReportContext {
const ExecutionProfiler &profiler;
const ExecutionProfiler::NameMapper &name_mapper;
vespalib::hash_map<TaskId,vespalib::string> name_cache;
ReportContext(const ExecutionProfiler &profiler_in,
const ExecutionProfiler::NameMapper &name_mapper_in, size_t num_names)
: profiler(profiler_in), name_mapper(name_mapper_in), name_cache(num_names * 2) {}
size_t get_max_depth() const { return profiler._max_depth; }
const vespalib::string &resolve_name(TaskId task) {
auto pos = name_cache.find(task);
if (pos == name_cache.end()) {
pos = name_cache.insert(std::make_pair(task, name_mapper(profiler.name_of(task)))).first;
}
return pos->second;
}
};
namespace {
double as_ms(duration d) {
return (count_ns(d) / 1000000.0);
}
class TreeProfiler : public ExecutionProfiler::Impl
{
private:
using ReportContext = ExecutionProfiler::ReportContext;
using TaskId = ExecutionProfiler::TaskId;
using NodeId = uint32_t;
using Edges = vespalib::hash_map<TaskId, NodeId>;
struct Node {
TaskId task;
size_t count;
duration total_time;
Edges children;
Node(TaskId task_in) noexcept
: task(task_in),
count(0),
total_time(),
children() {}
};
struct Frame {
NodeId node;
steady_time start;
Frame(NodeId node_in) noexcept
: node(node_in), start(steady_clock::now()) {}
};
std::vector<Node> _nodes;
Edges _roots;
std::vector<Frame> _state;
duration get_children_time(const Edges &edges) const {
duration result = duration::zero();
for (const auto &entry: edges) {
result += _nodes[entry.second].total_time;
}
return result;
}
std::vector<NodeId> get_sorted_children(const Edges &edges) const {
std::vector<uint32_t> children;
for (const auto &entry: edges) {
children.push_back(entry.second);
}
std::sort(children.begin(), children.end(),
[&](const auto &a, const auto &b) {
return (_nodes[a].total_time > _nodes[b].total_time);
});
return children;
}
void render_node(slime::Cursor &obj, NodeId node, ReportContext &ctx) const {
obj.setString("name", ctx.resolve_name(_nodes[node].task));
obj.setLong("count", _nodes[node].count);
obj.setDouble("total_time_ms", as_ms(_nodes[node].total_time));
if (!_nodes[node].children.empty()) {
auto children_time = get_children_time(_nodes[node].children);
obj.setDouble("self_time_ms", as_ms(_nodes[node].total_time - children_time));
render_children(obj.setArray("children"), _nodes[node].children, ctx);
}
}
void render_children(slime::Cursor &arr, const Edges &edges, ReportContext &ctx) const {
auto children = get_sorted_children(edges);
for (NodeId child: children) {
render_node(arr.addObject(), child, ctx);
}
}
public:
TreeProfiler() : _nodes(), _roots(), _state() {}
void track_start(TaskId task) override {
auto &edges = _state.empty() ? _roots : _nodes[_state.back().node].children;
auto [pos, was_new] = edges.insert(std::make_pair(task, _nodes.size()));
NodeId node = pos->second; // extending _nodes might invalidate lookup result
if (was_new) {
assert(node == _nodes.size());
_nodes.emplace_back(task);
}
assert(node < _nodes.size());
_state.emplace_back(node);
}
void track_complete() override {
assert(!_state.empty());
auto &node = _nodes[_state.back().node];
auto elapsed = steady_clock::now() - _state.back().start;
++node.count;
node.total_time += elapsed;
_state.pop_back();
}
void report(slime::Cursor &obj, ReportContext &ctx) const override {
obj.setString("profiler", "tree");
obj.setLong("depth", ctx.get_max_depth());
obj.setDouble("total_time_ms", as_ms(get_children_time(_roots)));
if (!_roots.empty()) {
render_children(obj.setArray("roots"), _roots, ctx);
}
}
};
class FlatProfiler : public ExecutionProfiler::Impl
{
private:
using ReportContext = ExecutionProfiler::ReportContext;
using TaskId = ExecutionProfiler::TaskId;
struct Node {
size_t count;
duration self_time;
Node() noexcept
: count(0),
self_time() {}
};
struct Frame {
TaskId task;
steady_time start;
duration overlap;
Frame(TaskId task_in) noexcept
: task(task_in), start(steady_clock::now()), overlap() {}
};
size_t _topn;
std::vector<Node> _nodes;
std::vector<Frame> _state;
duration get_total_time() const {
duration result = duration::zero();
for (const auto &node: _nodes) {
result += node.self_time;
}
return result;
}
std::vector<uint32_t> get_sorted_nodes() const {
std::vector<uint32_t> nodes;
nodes.reserve(_nodes.size());
for (uint32_t i = 0; i < _nodes.size(); ++i) {
if (_nodes[i].count > 0) {
nodes.push_back(i);
}
}
std::sort(nodes.begin(), nodes.end(),
[&](const auto &a, const auto &b) {
return (_nodes[a].self_time > _nodes[b].self_time);
});
return nodes;
}
void render_node(slime::Cursor &obj, uint32_t node, ReportContext &ctx) const {
obj.setString("name", ctx.resolve_name(node));
obj.setLong("count", _nodes[node].count);
obj.setDouble("self_time_ms", as_ms(_nodes[node].self_time));
}
public:
FlatProfiler(size_t topn) : _topn(topn), _nodes(), _state() {
_nodes.reserve(256);
_state.reserve(64);
}
void track_start(TaskId task) override {
if (task >= _nodes.size()) {
_nodes.resize(task + 1);
}
_state.emplace_back(task);
}
void track_complete() override {
assert(!_state.empty());
auto &state = _state.back();
auto &node = _nodes[state.task];
auto elapsed = steady_clock::now() - state.start;
++node.count;
node.self_time += (elapsed - state.overlap);
_state.pop_back();
if (!_state.empty()) {
_state.back().overlap += elapsed;
}
}
void report(slime::Cursor &obj, ReportContext &ctx) const override {
obj.setString("profiler", "flat");
obj.setLong("topn", _topn);
obj.setDouble("total_time_ms", as_ms(get_total_time()));
auto list = get_sorted_nodes();
if (auto limit = std::min(list.size(), _topn); limit > 0) {
auto &arr = obj.setArray("roots");
for (uint32_t i = 0; i < limit; ++i) {
render_node(arr.addObject(), list[i], ctx);
}
}
}
};
}
ExecutionProfiler::ExecutionProfiler(int32_t profile_depth)
: _level(0),
_max_depth(),
_names(),
_name_map(),
_impl()
{
if (profile_depth < 0) {
_max_depth = -1;
size_t topn = -profile_depth;
_impl = std::make_unique<FlatProfiler>(topn);
} else {
_max_depth = profile_depth;
_impl = std::make_unique<TreeProfiler>();
}
}
ExecutionProfiler::~ExecutionProfiler() = default;
ExecutionProfiler::TaskId
ExecutionProfiler::resolve(const vespalib::string &name)
{
auto [pos, was_new] = _name_map.insert(std::make_pair(name, _names.size()));
if (was_new) {
assert(pos->second == _names.size());
_names.push_back(name);
}
assert(pos->second < _names.size());
return pos->second;
}
void
ExecutionProfiler::report(slime::Cursor &obj, const NameMapper &name_mapper) const
{
ReportContext ctx(*this, name_mapper, _names.size());
_impl->report(obj, ctx);
}
}
|
