Skip to content

Commit 0601d1d

Browse files
ioquatixioquatix
committed
Fix profiling.
1 parent 77f0664 commit 0601d1d

File tree

4 files changed

+109
-36
lines changed

4 files changed

+109
-36
lines changed

‎ext/io/event/event.c‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
// Copyright, 2021-2025, by Samuel Williams.
33

44
#include "event.h"
5+
#include "profile.h"
56
#include "selector/selector.h"
67

78
void Init_IO_Event(void)
@@ -11,8 +12,10 @@ void Init_IO_Event(void)
1112
#endif
1213

1314
VALUE IO_Event = rb_define_module_under(rb_cIO, "Event");
14-
VALUE IO_Event_Selector = rb_define_module_under(IO_Event, "Selector");
1515

16+
Init_IO_Event_Profile(IO_Event);
17+
18+
VALUE IO_Event_Selector = rb_define_module_under(IO_Event, "Selector");
1619
Init_IO_Event_Selector(IO_Event_Selector);
1720

1821
#ifdef IO_EVENT_SELECTOR_URING

‎ext/io/event/profile.c‎

Lines changed: 73 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,8 @@
88

99
#include <stdio.h>
1010

11+
VALUE IO_Event_Profile = Qnil;
12+
1113
void IO_Event_Profile_Call_initialize(struct IO_Event_Profile_Call *call) {
1214
call->enter_time.tv_sec = 0;
1315
call->enter_time.tv_nsec = 0;
@@ -29,6 +31,50 @@ void IO_Event_Profile_Call_free(struct IO_Event_Profile_Call *call) {
2931
}
3032
}
3133

34+
static void IO_Event_Profile_mark(void *ptr) {
35+
struct IO_Event_Profile *profile = (struct IO_Event_Profile*)ptr;
36+
37+
// If `klass` is stored as a VALUE in calls, we need to mark them here:
38+
for (size_t i = 0; i < profile->calls.limit; i += 1) {
39+
struct IO_Event_Profile_Call *call = profile->calls.base[i];
40+
rb_gc_mark(call->klass);
41+
}
42+
}
43+
44+
static void IO_Event_Profile_free(void *ptr) {
45+
struct IO_Event_Profile *profile = (struct IO_Event_Profile*)ptr;
46+
47+
IO_Event_Array_free(&profile->calls);
48+
49+
free(profile);
50+
}
51+
52+
const rb_data_type_t IO_Event_Profile_Type = {
53+
.wrap_struct_name = "IO_Event_Profile",
54+
.function = {
55+
.dmark = IO_Event_Profile_mark,
56+
.dfree = IO_Event_Profile_free,
57+
},
58+
.flags = RUBY_TYPED_FREE_IMMEDIATELY,
59+
};
60+
61+
VALUE IO_Event_Profile_allocate(VALUE klass) {
62+
struct IO_Event_Profile *profile = ALLOC(struct IO_Event_Profile);
63+
64+
profile->calls.element_initialize = (void (*)(void*))IO_Event_Profile_Call_initialize;
65+
profile->calls.element_free = (void (*)(void*))IO_Event_Profile_Call_free;
66+
67+
IO_Event_Array_initialize(&profile->calls, 0, sizeof(struct IO_Event_Profile_Call));
68+
69+
return TypedData_Wrap_Struct(klass, &IO_Event_Profile_Type, profile);
70+
}
71+
72+
struct IO_Event_Profile *IO_Event_Profile_get(VALUE self) {
73+
struct IO_Event_Profile *profile;
74+
TypedData_Get_Struct(self, struct IO_Event_Profile, &IO_Event_Profile_Type, profile);
75+
return profile;
76+
}
77+
3278
int event_flag_call_p(rb_event_flag_t event_flags) {
3379
return event_flags & (RUBY_EVENT_CALL | RUBY_EVENT_C_CALL);
3480
}
@@ -38,7 +84,7 @@ int event_flag_return_p(rb_event_flag_t event_flags) {
3884
}
3985

4086
static void profile_event_callback(rb_event_flag_t event_flag, VALUE data, VALUE self, ID id, VALUE klass) {
41-
struct IO_Event_Profile *profile = (struct IO_Event_Profile*)data;
87+
struct IO_Event_Profile *profile = IO_Event_Profile_get(data);
4288

4389
if (event_flag_call_p(event_flag)) {
4490
struct IO_Event_Profile_Call *call = IO_Event_Array_push(&profile->calls);
@@ -77,39 +123,38 @@ static void profile_event_callback(rb_event_flag_t event_flag, VALUE data, VALUE
77123
}
78124
}
79125

80-
void IO_Event_Profile_initialize(struct IO_Event_Profile *profile, VALUE fiber) {
81-
profile->fiber = fiber;
82-
83-
profile->calls.element_initialize = (void (*)(void*))IO_Event_Profile_Call_initialize;
84-
profile->calls.element_free = (void (*)(void*))IO_Event_Profile_Call_free;
126+
void IO_Event_Profile_start(VALUE self, int track_calls) {
127+
struct IO_Event_Profile *profile = IO_Event_Profile_get(self);
85128

86-
IO_Event_Array_initialize(&profile->calls, 0, sizeof(struct IO_Event_Profile_Call));
87-
}
88-
89-
void IO_Event_Profile_start(struct IO_Event_Profile *profile) {
90129
IO_Event_Time_current(&profile->start_time);
91130
profile->nesting = 0;
92131
profile->current = NULL;
93132

133+
profile->track_calls = track_calls;
134+
94135
// Since fibers are currently limited to a single thread, we use this in the hope that it's a little more efficient:
95-
VALUE thread = rb_thread_current();
96-
rb_thread_add_event_hook(thread, profile_event_callback, RUBY_EVENT_CALL | RUBY_EVENT_C_CALL | RUBY_EVENT_RETURN | RUBY_EVENT_C_RETURN, (VALUE)profile);
136+
if (profile->track_calls) {
137+
VALUE thread = rb_thread_current();
138+
rb_thread_add_event_hook(thread, profile_event_callback, RUBY_EVENT_CALL | RUBY_EVENT_C_CALL | RUBY_EVENT_RETURN | RUBY_EVENT_C_RETURN, self);
139+
}
97140
}
98141

99-
void IO_Event_Profile_stop(struct IO_Event_Profile *profile) {
142+
void IO_Event_Profile_stop(VALUE self) {
143+
struct IO_Event_Profile *profile = IO_Event_Profile_get(self);
144+
100145
IO_Event_Time_current(&profile->stop_time);
101146

102-
VALUE thread = rb_thread_current();
103-
rb_thread_remove_event_hook_with_data(thread, profile_event_callback, (VALUE)profile);
104-
}
105-
106-
void IO_Event_Profile_free(struct IO_Event_Profile *profile) {
107-
IO_Event_Array_free(&profile->calls);
147+
if (profile->track_calls) {
148+
VALUE thread = rb_thread_current();
149+
rb_thread_remove_event_hook_with_data(thread, profile_event_callback, self);
150+
}
108151
}
109152

110153
static const float IO_EVENT_PROFILE_PRINT_MINIMUM_PROPORTION = 0.01;
111154

112-
void IO_Event_Profile_print(FILE *restrict stream, struct IO_Event_Profile *profile) {
155+
void IO_Event_Profile_print(VALUE self, FILE *restrict stream) {
156+
struct IO_Event_Profile *profile = IO_Event_Profile_get(self);
157+
113158
struct timespec total_duration = {};
114159
IO_Event_Time_elapsed(&profile->start_time, &profile->stop_time, &total_duration);
115160

@@ -132,11 +177,18 @@ void IO_Event_Profile_print(FILE *restrict stream, struct IO_Event_Profile *prof
132177
fputc('\t', stream);
133178
}
134179

180+
VALUE class_inspect = rb_inspect(call->klass);
135181
const char *name = rb_id2name(call->id);
136-
fprintf(stream, "\t%s:%d in '%s#%s' (" IO_EVENT_TIME_PRINTF_TIMESPEC "s)\n", call->path, call->line, RSTRING_PTR(rb_inspect(call->klass)), name, IO_EVENT_TIME_PRINTF_TIMESPEC_ARGUMENTS(duration));
182+
183+
fprintf(stream, "\t%s:%d in '%s#%s' (" IO_EVENT_TIME_PRINTF_TIMESPEC "s)\n", call->path, call->line, RSTRING_PTR(class_inspect), name, IO_EVENT_TIME_PRINTF_TIMESPEC_ARGUMENTS(duration));
137184
}
138185

139186
if (skipped > 0) {
140187
fprintf(stream, "Skipped %zu calls that were too short to be meaningful.\n", skipped);
141188
}
142189
}
190+
191+
void Init_IO_Event_Profile(VALUE IO_Event) {
192+
IO_Event_Profile = rb_define_class_under(IO_Event, "Profile", rb_cObject);
193+
rb_define_alloc_func(IO_Event_Profile, IO_Event_Profile_allocate);
194+
}

‎ext/io/event/profile.h‎

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@
77
#include "array.h"
88
#include "time.h"
99

10+
extern VALUE IO_Event_Profile;
11+
1012
struct IO_Event_Profile_Call {
1113
struct timespec enter_time;
1214
struct timespec exit_time;
@@ -24,7 +26,7 @@ struct IO_Event_Profile_Call {
2426
};
2527

2628
struct IO_Event_Profile {
27-
VALUE fiber;
29+
int track_calls;
2830

2931
struct timespec start_time;
3032
struct timespec stop_time;
@@ -38,18 +40,24 @@ struct IO_Event_Profile {
3840
struct IO_Event_Array calls;
3941
};
4042

41-
void IO_Event_Profile_initialize(struct IO_Event_Profile *profile, VALUE fiber);
43+
extern const rb_data_type_t IO_Event_Profile_Type;
44+
VALUE IO_Event_Profile_allocate(VALUE klass);
45+
struct IO_Event_Profile *IO_Event_Profile_get(VALUE self);
4246

43-
void IO_Event_Profile_start(struct IO_Event_Profile *profile);
44-
void IO_Event_Profile_stop(struct IO_Event_Profile *profile);
47+
void IO_Event_Profile_initialize(struct IO_Event_Profile *profile, VALUE fiber);
48+
void IO_Event_Profile_start(VALUE self, int track_calls);
49+
void IO_Event_Profile_stop(VALUE self);
4550

46-
void IO_Event_Profile_free(struct IO_Event_Profile *profile);
47-
void IO_Event_Profile_print(FILE *restrict stream, struct IO_Event_Profile *profile);
51+
void IO_Event_Profile_print(VALUE profile, FILE *restrict stream);
4852

49-
static inline float IO_Event_Profile_duration(struct IO_Event_Profile *profile) {
53+
static inline float IO_Event_Profile_duration(VALUE self) {
54+
struct IO_Event_Profile *profile = IO_Event_Profile_get(self);
55+
5056
struct timespec duration;
5157

5258
IO_Event_Time_elapsed(&profile->start_time, &profile->stop_time, &duration);
5359

5460
return IO_Event_Time_duration(&duration);
5561
}
62+
63+
void Init_IO_Event_Profile(VALUE IO_Event);

‎ext/io/event/selector/selector.c‎

Lines changed: 17 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ static const int DEBUG = 0;
1212
static ID id_transfer, id_alive_p;
1313

1414
static float IO_Event_Selector_stall_log_threshold = 0;
15+
static int IO_Event_Selector_stall_log_profile = 0;
1516

1617
VALUE IO_Event_Selector_fiber_transfer(VALUE fiber, int argc, VALUE *argv) {
1718
// TODO Consider introducing something like `rb_fiber_scheduler_transfer(...)`.
@@ -37,20 +38,21 @@ VALUE IO_Event_Selector_fiber_transfer_user(VALUE fiber, int argc, VALUE *argv)
3738
return IO_Event_Selector_fiber_transfer(fiber, argc, argv);
3839
}
3940

40-
struct IO_Event_Profile profile;
41-
IO_Event_Profile_initialize(&profile, fiber);
42-
IO_Event_Profile_start(&profile);
41+
VALUE profile = IO_Event_Profile_allocate(IO_Event_Profile);
42+
43+
IO_Event_Profile_start(profile, IO_Event_Selector_stall_log_profile);
4344

4445
// Transfer control to the fiber:
4546
VALUE result = IO_Event_Selector_fiber_transfer(fiber, argc, argv);
4647

47-
IO_Event_Profile_stop(&profile);
48+
IO_Event_Profile_stop(profile);
4849

49-
float duration = IO_Event_Profile_duration(&profile);
50+
float duration = IO_Event_Profile_duration(profile);
5051

5152
if (duration > IO_Event_Selector_stall_log_threshold) {
5253
fprintf(stderr, "Fiber stalled for %.3f seconds\n", duration);
53-
IO_Event_Profile_print(stderr, &profile);
54+
55+
IO_Event_Profile_print(profile, stderr);
5456
}
5557

5658
return result;
@@ -179,7 +181,7 @@ void Init_IO_Event_Selector(VALUE IO_Event_Selector) {
179181

180182
if (stall_log_threshold) {
181183
if (strcmp(stall_log_threshold, "true") == 0) {
182-
IO_Event_Selector_stall_log_threshold = 0.001;
184+
IO_Event_Selector_stall_log_threshold = 0.01;
183185
} else if (strcmp(stall_log_threshold, "false") == 0) {
184186
IO_Event_Selector_stall_log_threshold = 0;
185187
} else {
@@ -188,6 +190,14 @@ void Init_IO_Event_Selector(VALUE IO_Event_Selector) {
188190

189191
if (DEBUG) fprintf(stderr, "IO_EVENT_SELECTOR_STALL_LOG_THRESHOLD = %.3f\n", IO_Event_Selector_stall_log_threshold);
190192
}
193+
194+
char *stall_log_profile = getenv("IO_EVENT_SELECTOR_STALL_LOG_PROFILE");
195+
196+
if (stall_log_profile) {
197+
if (strcmp(stall_log_profile, "true") == 0) {
198+
IO_Event_Selector_stall_log_profile = 1;
199+
}
200+
}
191201
}
192202

193203
struct wait_and_transfer_arguments {

0 commit comments

Comments
 (0)