Skip to content

Commit ca33d49

Browse files
tarun292facebook-github-bot
tarun292
authored and
facebook-github-bot
committed
ETDump changes for delegate logging.
Differential Revision: D48993977 fbshipit-source-id: 23197f9e57e762297ac387b2ce7d08d9ce13caa4
1 parent f586b59 commit ca33d49

File tree

4 files changed

+253
-34
lines changed

4 files changed

+253
-34
lines changed

‎sdk/etdump/etdump_flatcc.cpp

Lines changed: 124 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
*/
88

99
#include "executorch/sdk/etdump/etdump_flatcc.h"
10+
#include <stdio.h>
1011
#include <string.h>
1112
#include "executorch/runtime/platform/assert.h"
1213

@@ -18,7 +19,7 @@ ETDumpGen::ETDumpGen(void* buffer, size_t buf_size) {
1819
// Initialize the flatcc builder using the buffer and buffer size
1920
flatcc_builder_init(&builder);
2021
flatbuffers_buffer_start(&builder, etdump_ETDump_file_identifier);
21-
etdump_ETDump_start(&builder);
22+
etdump_ETDump_start_as_root_with_size(&builder);
2223
etdump_ETDump_version_add(&builder, ETDUMP_VERSION);
2324
etdump_ETDump_run_data_start(&builder);
2425
etdump_ETDump_run_data_push_start(&builder);
@@ -49,6 +50,19 @@ int64_t ETDumpGen::create_string_entry(const char* name) {
4950
return flatbuffers_string_create_str(&builder, name);
5051
}
5152

53+
// ETDumpGen has the following possible states, ETDumpGen_Init,
54+
// ETDumpGen_Block_Created, ETDumpGen_Adding_Allocators,
55+
// ETDumpGen_Adding_Events. Right after boot-up the state of ETDump will be
56+
// ETDumpGen_Init. At this point we have an option of adding allocators that
57+
// we want to track. Once we've completed adding the allocators we want to track
58+
// we will close the allocators table and move ETDumpGen to the
59+
// ETDumpGen_Adding_Events state. After this point we can start adding events to
60+
// ETDump as we wish.
61+
// The reason we need to maintain this state machine inside of ETDumpGen is
62+
// because, once a table of one type has been closed and another table of a
63+
// different type is opened after it we cannot open another table of the first
64+
// type again. In this case once we close the allocators table and start pushing
65+
// to the events table we cannot push to the allocators table again.
5266
void ETDumpGen::check_ready_to_add_events() {
5367
if (etdump_gen_state != ETDumpGen_Adding_Events) {
5468
ET_CHECK_MSG(
@@ -68,12 +82,12 @@ EventTracerEntry ETDumpGen::start_profiling(
6882
ChainID chain_id,
6983
DebugHandle debug_handle) {
7084
EventTracerEntry prof_entry;
71-
prof_entry.event_id = create_string_entry(name);
85+
prof_entry.event_id = name != nullptr ? create_string_entry(name) : -1;
86+
prof_entry.delegate_event_id_type = DelegateDebugIdType::kNone;
7287

73-
if (chain_id == -1 && debug_handle == 0) {
88+
if (chain_id == -1) {
7489
prof_entry.chain_id = chain_id_;
7590
prof_entry.debug_handle = debug_handle_;
76-
7791
} else {
7892
prof_entry.chain_id = chain_id;
7993
prof_entry.debug_handle = debug_handle;
@@ -84,22 +98,115 @@ EventTracerEntry ETDumpGen::start_profiling(
8498

8599
// TODO: Update all occurrences of the ProfileEvent calls once the
86100
// EventTracerEntry struct is updated.
87-
void ETDumpGen::end_profiling(EventTracerEntry prof_entry) {
101+
EventTracerEntry ETDumpGen::start_profiling_delegate(
102+
const char* name,
103+
DebugHandle delegate_debug_index) {
104+
ET_CHECK_MSG(
105+
(name == nullptr) || (delegate_debug_index == -1),
106+
"Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
107+
check_ready_to_add_events();
108+
EventTracerEntry prof_entry;
109+
DelegateDebugIdType delegate_event_id_type =
110+
name == nullptr ? DelegateDebugIdType::kInt : DelegateDebugIdType::kStr;
111+
prof_entry.delegate_event_id_type = delegate_event_id_type;
112+
prof_entry.chain_id = chain_id_;
113+
prof_entry.debug_handle = debug_handle_;
114+
prof_entry.event_id = delegate_debug_index == static_cast<unsigned int>(-1) ? create_string_entry(name)
115+
: delegate_debug_index;
116+
prof_entry.start_time = et_pal_current_ticks();
117+
return prof_entry;
118+
}
119+
120+
void ETDumpGen::end_profiling_delegate(
121+
EventTracerEntry event_tracer_entry,
122+
const char* metadata) {
88123
et_timestamp_t end_time = et_pal_current_ticks();
89124
check_ready_to_add_events();
125+
126+
int64_t string_id_metadata =
127+
metadata == nullptr ? -1 : create_string_entry(metadata);
128+
129+
// Start building the ProfileEvent entry.
130+
etdump_ProfileEvent_start(&builder);
131+
etdump_ProfileEvent_start_time_add(&builder, event_tracer_entry.start_time);
132+
etdump_ProfileEvent_end_time_add(&builder, end_time);
133+
etdump_ProfileEvent_chain_id_add(&builder, chain_id_);
134+
etdump_ProfileEvent_instruction_id_add(&builder, debug_handle_);
135+
// Delegate debug identifier can either be of a string type or an integer
136+
// type. If it's a string type then it's a value of type
137+
// flatbuffers_string_ref_t type, whereas if it's an integer type then we
138+
// write the integer value directly.
139+
if (event_tracer_entry.delegate_event_id_type == DelegateDebugIdType::kInt) {
140+
etdump_ProfileEvent_delegate_debug_id_int_add(
141+
&builder, event_tracer_entry.event_id);
142+
} else {
143+
etdump_ProfileEvent_delegate_debug_id_str_add(
144+
&builder, event_tracer_entry.event_id);
145+
}
146+
// String metadata is optional and if a nullptr is passed in then we don't
147+
// add anything.
148+
if (string_id_metadata != -1) {
149+
etdump_ProfileEvent_delegate_debug_metadata_add(
150+
&builder, string_id_metadata);
151+
}
152+
etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
90153
etdump_RunData_events_push_start(&builder);
154+
etdump_Event_profile_event_add(&builder, id);
155+
etdump_RunData_events_push_end(&builder);
156+
}
91157

92-
etdump_Event_profile_event_create(
93-
&builder,
94-
prof_entry.event_id, // see todo - change to prof_entry.name
95-
prof_entry.chain_id,
96-
-1, // see todo - change to prof_entry.instruction_id
97-
prof_entry.debug_handle, // see todo - change to
98-
// prof_entry.delegate_debug_id_int
99-
flatbuffers_string_create_str(
100-
&builder, ""), // see todo - change to prof_entry.dlegate_debug_id_str
101-
prof_entry.start_time,
102-
end_time);
158+
void ETDumpGen::log_profiling_delegate(
159+
const char* name,
160+
DebugHandle delegate_debug_index,
161+
et_timestamp_t start_time,
162+
et_timestamp_t end_time,
163+
const char* metadata) {
164+
ET_CHECK_MSG(
165+
(name == nullptr) || (delegate_debug_index == -1),
166+
"Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
167+
check_ready_to_add_events();
168+
int64_t string_id = name != nullptr ? create_string_entry(name) : -1;
169+
int64_t string_id_metadata =
170+
metadata == nullptr ? -1 : create_string_entry(metadata);
171+
etdump_ProfileEvent_start(&builder);
172+
etdump_ProfileEvent_start_time_add(&builder, start_time);
173+
etdump_ProfileEvent_end_time_add(&builder, end_time);
174+
etdump_ProfileEvent_chain_id_add(&builder, chain_id_);
175+
etdump_ProfileEvent_instruction_id_add(&builder, debug_handle_);
176+
if (string_id == -1) {
177+
etdump_ProfileEvent_delegate_debug_id_int_add(
178+
&builder, delegate_debug_index);
179+
} else {
180+
etdump_ProfileEvent_delegate_debug_id_str_add(&builder, string_id);
181+
}
182+
if (string_id_metadata != -1) {
183+
etdump_ProfileEvent_delegate_debug_metadata_add(
184+
&builder, string_id_metadata);
185+
}
186+
etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
187+
etdump_RunData_events_push_start(&builder);
188+
etdump_Event_profile_event_add(&builder, id);
189+
etdump_RunData_events_push_end(&builder);
190+
}
191+
192+
void ETDumpGen::end_profiling(EventTracerEntry prof_entry) {
193+
et_timestamp_t end_time = et_pal_current_ticks();
194+
ET_CHECK_MSG(
195+
prof_entry.delegate_event_id_type == DelegateDebugIdType::kNone,
196+
"Delegate events must use end_profiling_delegate to mark the end of a delegate profiling event.");
197+
check_ready_to_add_events();
198+
199+
etdump_ProfileEvent_start(&builder);
200+
etdump_ProfileEvent_start_time_add(&builder, prof_entry.start_time);
201+
etdump_ProfileEvent_end_time_add(&builder, end_time);
202+
etdump_ProfileEvent_chain_id_add(&builder, prof_entry.chain_id);
203+
etdump_ProfileEvent_instruction_id_add(&builder, prof_entry.debug_handle);
204+
if (prof_entry.event_id != -1) {
205+
etdump_ProfileEvent_name_add(&builder, prof_entry.event_id);
206+
}
207+
etdump_ProfileEvent_ref_t id = etdump_ProfileEvent_end(&builder);
208+
etdump_RunData_events_push_start(&builder);
209+
etdump_Event_profile_event_add(&builder, id);
103210
etdump_RunData_events_push_end(&builder);
104211
}
105212

@@ -122,8 +229,6 @@ void ETDumpGen::track_allocation(
122229
size_t allocation_size) {
123230
check_ready_to_add_events();
124231

125-
// etdump_AllocationEvent_ref_t alloc_event_ref =
126-
// etdump_AllocationEvent_create(&builder, allocator_id, allocation_size);
127232
etdump_RunData_events_push_start(&builder);
128233
etdump_Event_allocation_event_create(&builder, allocator_id, allocation_size);
129234
etdump_RunData_events_push_end(&builder);
@@ -151,5 +256,6 @@ etdump_result ETDumpGen::get_etdump_data() {
151256
size_t ETDumpGen::get_num_blocks() {
152257
return num_blocks;
153258
}
259+
154260
} // namespace executor
155261
} // namespace torch

‎sdk/etdump/etdump_flatcc.h

Lines changed: 6 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -43,22 +43,20 @@ class ETDumpGen : public EventTracer {
4343
ChainID chain_id = -1,
4444
DebugHandle debug_handle = 0) override;
4545
virtual void end_profiling(EventTracerEntry prof_entry) override;
46-
virtual void track_allocation(AllocatorID id, size_t size) override;
47-
virtual AllocatorID track_allocator(const char* name) override;
4846
virtual EventTracerEntry start_profiling_delegate(
4947
const char* name,
50-
DebugHandle delegate_debug_index) override {
51-
return EventTracerEntry();
52-
};
48+
DebugHandle delegate_debug_index) override;
5349
virtual void end_profiling_delegate(
54-
EventTracerEntry event_tracer_entry,
55-
const char* metadata = nullptr) override{};
50+
EventTracerEntry prof_entry,
51+
const char* metadata) override;
5652
virtual void log_profiling_delegate(
5753
const char* name,
5854
DebugHandle delegate_debug_index,
5955
et_timestamp_t start_time,
6056
et_timestamp_t end_time,
61-
const char* metadata = nullptr) override{};
57+
const char* metadata) override;
58+
virtual void track_allocation(AllocatorID id, size_t size) override;
59+
virtual AllocatorID track_allocator(const char* name) override;
6260
etdump_result get_etdump_data();
6361
size_t get_num_blocks();
6462

‎sdk/etdump/etdump_schema_flatcc.fbs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -97,6 +97,9 @@ table ProfileEvent {
9797
// String based delegate debug identifier.
9898
delegate_debug_id_str:string;
9999

100+
// Delegate debug metadata free form string.
101+
delegate_debug_metadata:string;
102+
100103
// Time at which this event started. Could be in units of time or CPU cycles.
101104
start_time:ulong;
102105

‎sdk/etdump/tests/etdump_test.cpp

Lines changed: 120 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -46,8 +46,10 @@ TEST_F(ProfilerETDumpTest, SingleProfileEvent) {
4646
ASSERT_TRUE(result.buf != nullptr);
4747
ASSERT_TRUE(result.size != 0);
4848

49-
etdump_ETDump_table_t etdump = etdump_ETDump_as_root_with_identifier(
50-
result.buf, etdump_ETDump_file_identifier);
49+
size_t size = 0;
50+
void* buf = flatbuffers_read_size_prefix(result.buf, &size);
51+
etdump_ETDump_table_t etdump =
52+
etdump_ETDump_as_root_with_identifier(buf, etdump_ETDump_file_identifier);
5153

5254
ASSERT_NE(etdump, nullptr);
5355
EXPECT_EQ(etdump_ETDump_version(etdump), ETDUMP_VERSION);
@@ -90,8 +92,10 @@ TEST_F(ProfilerETDumpTest, EmptyBlocks) {
9092
ASSERT_TRUE(result.buf != nullptr);
9193
ASSERT_TRUE(result.size != 0);
9294

93-
etdump_ETDump_table_t etdump = etdump_ETDump_as_root_with_identifier(
94-
result.buf, etdump_ETDump_file_identifier);
95+
size_t size = 0;
96+
void* buf = flatbuffers_read_size_prefix(result.buf, &size);
97+
etdump_ETDump_table_t etdump =
98+
etdump_ETDump_as_root_with_identifier(buf, etdump_ETDump_file_identifier);
9599

96100
etdump_RunData_vec_t run_data_vec = etdump_ETDump_run_data(etdump);
97101
ASSERT_EQ(etdump_RunData_vec_len(run_data_vec), 3);
@@ -153,8 +157,10 @@ TEST_F(ProfilerETDumpTest, MultipleBlocksWithEvents) {
153157
ASSERT_TRUE(result.buf != nullptr);
154158
ASSERT_TRUE(result.size != 0);
155159

156-
etdump_ETDump_table_t etdump = etdump_ETDump_as_root_with_identifier(
157-
result.buf, etdump_ETDump_file_identifier);
160+
size_t size = 0;
161+
void* buf = flatbuffers_read_size_prefix(result.buf, &size);
162+
etdump_ETDump_table_t etdump =
163+
etdump_ETDump_as_root_with_identifier(buf, etdump_ETDump_file_identifier);
158164

159165
ASSERT_NE(etdump, nullptr);
160166
EXPECT_EQ(etdump_ETDump_version(etdump), ETDUMP_VERSION);
@@ -212,8 +218,10 @@ TEST_F(ProfilerETDumpTest, VerifyData) {
212218
ASSERT_TRUE(result.buf != nullptr);
213219
ASSERT_TRUE(result.size != 0);
214220

215-
etdump_ETDump_table_t etdump = etdump_ETDump_as_root_with_identifier(
216-
result.buf, etdump_ETDump_file_identifier);
221+
size_t size = 0;
222+
void* buf = flatbuffers_read_size_prefix(result.buf, &size);
223+
etdump_ETDump_table_t etdump =
224+
etdump_ETDump_as_root_with_identifier(buf, etdump_ETDump_file_identifier);
217225

218226
ASSERT_NE(etdump, nullptr);
219227
EXPECT_EQ(etdump_ETDump_version(etdump), ETDUMP_VERSION);
@@ -254,5 +262,109 @@ TEST_F(ProfilerETDumpTest, VerifyData) {
254262
free(result.buf);
255263
}
256264

265+
TEST_F(ProfilerETDumpTest, LogDelegateEvents) {
266+
etdump_gen->create_event_block("test_block");
267+
268+
// Event 0
269+
etdump_gen->log_profiling_delegate(nullptr, 276, 1, 2, nullptr);
270+
// Event 1
271+
etdump_gen->log_profiling_delegate(nullptr, 278, 1, 2, "test_metadata");
272+
EventTracerEntry entry = etdump_gen->start_profiling_delegate(
273+
"test_event", static_cast<torch::executor::DebugHandle>(-1));
274+
EXPECT_NE(entry.delegate_event_id_type, DelegateDebugIdType::kNone);
275+
// Event 2
276+
etdump_gen->end_profiling_delegate(entry, "test_metadata");
277+
// Event 3
278+
etdump_gen->log_profiling_delegate(
279+
"test_event",
280+
static_cast<torch::executor::DebugHandle>(-1),
281+
1,
282+
2,
283+
nullptr);
284+
// Event 4
285+
etdump_gen->log_profiling_delegate(
286+
"test_event",
287+
static_cast<torch::executor::DebugHandle>(-1),
288+
1,
289+
2,
290+
"test_metadata");
291+
292+
// Only a valid name or delegate debug index should be passed in. If valid
293+
// entries are passed in for both then the test should assert out.
294+
ET_EXPECT_DEATH(
295+
etdump_gen->start_profiling_delegate("test_event", 1),
296+
"Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
297+
ET_EXPECT_DEATH(
298+
etdump_gen->log_profiling_delegate("test_event", 1, 1, 2, nullptr),
299+
"Only name or delegate_debug_index can be valid. Check DelegateMappingBuilder documentation for more details.");
300+
ET_EXPECT_DEATH(
301+
etdump_gen->end_profiling(entry),
302+
"Delegate events must use end_profiling_delegate to mark the end of a delegate profiling event.");
303+
304+
etdump_result result = etdump_gen->get_etdump_data();
305+
ASSERT_TRUE(result.buf != nullptr);
306+
ASSERT_TRUE(result.size != 0);
307+
308+
// Run verification tests on the data that was just serialized.
309+
size_t size = 0;
310+
void* buf = flatbuffers_read_size_prefix(result.buf, &size);
311+
etdump_ETDump_table_t etdump =
312+
etdump_ETDump_as_root_with_identifier(buf, etdump_ETDump_file_identifier);
313+
etdump_RunData_vec_t run_data_vec = etdump_ETDump_run_data(etdump);
314+
315+
// Event 0
316+
etdump_RunData_table_t run_data_0 = etdump_RunData_vec_at(run_data_vec, 0);
317+
etdump_Event_vec_t event_vec = etdump_RunData_events(run_data_0);
318+
ASSERT_EQ(etdump_Event_vec_len(event_vec), 5);
319+
etdump_Event_table_t event = etdump_Event_vec_at(event_vec, 0);
320+
321+
flatbuffers_string_t delegate_debug_id_name =
322+
etdump_ProfileEvent_delegate_debug_id_str(
323+
etdump_Event_profile_event(event));
324+
325+
// Event 0 should have a empty delegate_debug_id_str
326+
EXPECT_EQ(delegate_debug_id_name, nullptr);
327+
// Check for the correct delegate_debug_id_int
328+
EXPECT_EQ(
329+
etdump_ProfileEvent_delegate_debug_id_int(
330+
etdump_Event_profile_event(event)),
331+
276);
332+
flatbuffers_string_t debug_metadata_name =
333+
etdump_ProfileEvent_delegate_debug_metadata(
334+
etdump_Event_profile_event(event));
335+
// Event 0 should have an empty delegate_debug_metadata string.
336+
EXPECT_EQ(debug_metadata_name, nullptr);
337+
338+
// Event 1
339+
event = etdump_Event_vec_at(event_vec, 1);
340+
// Check for the correct delegate_debug_id_int
341+
EXPECT_EQ(
342+
etdump_ProfileEvent_delegate_debug_id_int(
343+
etdump_Event_profile_event(event)),
344+
278);
345+
debug_metadata_name = etdump_ProfileEvent_delegate_debug_metadata(
346+
etdump_Event_profile_event(event));
347+
// Check for the correct delegate_debug_metadata string
348+
EXPECT_EQ(
349+
std::string(debug_metadata_name, strlen(debug_metadata_name)),
350+
"test_metadata");
351+
352+
// Event 2
353+
event = etdump_Event_vec_at(event_vec, 2);
354+
delegate_debug_id_name = etdump_ProfileEvent_delegate_debug_id_str(
355+
etdump_Event_profile_event(event));
356+
// Check for the correct delegate_debug_id_str string.
357+
EXPECT_EQ(
358+
std::string(delegate_debug_id_name, strlen(delegate_debug_id_name)),
359+
"test_event");
360+
// Event 2 used a string delegate debug identifier, so delegate_debug_id_int
361+
// should be -1.
362+
EXPECT_EQ(
363+
etdump_ProfileEvent_delegate_debug_id_int(
364+
etdump_Event_profile_event(event)),
365+
-1);
366+
free(result.buf);
367+
}
368+
257369
} // namespace executor
258370
} // namespace torch

0 commit comments

Comments
 (0)