Skip to content

Commit aa63130

Browse files
ioquatixioquatix
committed
Better handling of unmatched returns.
1 parent 829146e commit aa63130

File tree

2 files changed

+78
-56
lines changed

2 files changed

+78
-56
lines changed

‎ext/io/event/profiler.c‎

Lines changed: 77 additions & 55 deletions
Original file line numberDiff line numberDiff line change
@@ -121,100 +121,121 @@ int event_flag_return_p(rb_event_flag_t event_flags) {
121121
return event_flags & (RUBY_EVENT_RETURN | RUBY_EVENT_C_RETURN);
122122
}
123123

124+
const char *event_flag_name(rb_event_flag_t event_flag) {
125+
switch (event_flag) {
126+
case RUBY_EVENT_CALL: return "call";
127+
case RUBY_EVENT_C_CALL: return "c-call";
128+
case RUBY_EVENT_RETURN: return "return";
129+
case RUBY_EVENT_C_RETURN: return "c-return";
130+
default: return "unknown";
131+
}
132+
}
133+
134+
static struct IO_Event_Profiler_Call* profiler_event_record_call(struct IO_Event_Profiler *profiler, rb_event_flag_t event_flag, ID id, VALUE klass) {
135+
struct IO_Event_Profiler_Call *call = IO_Event_Array_push(&profiler->calls);
136+
137+
call->event_flag = event_flag;
138+
139+
call->parent = profiler->current;
140+
profiler->current = call;
141+
142+
call->nesting = profiler->nesting;
143+
profiler->nesting += 1;
144+
145+
if (id) {
146+
call->id = id;
147+
call->klass = klass;
148+
} else {
149+
rb_frame_method_id_and_class(&call->id, &call->klass);
150+
}
151+
152+
const char *path = rb_sourcefile();
153+
if (path) {
154+
call->path = strdup(path);
155+
}
156+
call->line = rb_sourceline();
157+
158+
return call;
159+
}
160+
124161
static void profiler_event_callback(rb_event_flag_t event_flag, VALUE data, VALUE self, ID id, VALUE klass) {
125162
struct IO_Event_Profiler *profiler = IO_Event_Profiler_get(data);
126163

127164
if (event_flag_call_p(event_flag)) {
128-
struct IO_Event_Profiler_Call *call = IO_Event_Array_push(&profiler->calls);
165+
struct IO_Event_Profiler_Call *call = profiler_event_record_call(profiler, event_flag, id, klass);
129166
IO_Event_Time_current(&call->enter_time);
130-
131-
call->event_flag = event_flag;
132-
133-
call->parent = profiler->current;
134-
profiler->current = call;
135-
136-
call->nesting = profiler->nesting;
137-
profiler->nesting += 1;
138-
139-
if (id) {
140-
call->id = id;
141-
call->klass = klass;
142-
} else {
143-
rb_frame_method_id_and_class(&call->id, &call->klass);
144-
}
145-
146-
const char *path = rb_sourcefile();
147-
if (path) {
148-
call->path = strdup(path);
149-
}
150-
call->line = rb_sourceline();
151167
} else if (event_flag_return_p(event_flag)) {
152168
struct IO_Event_Profiler_Call *call = profiler->current;
153169

154-
// Bad call sequence?
155-
if (call == NULL) return;
170+
// We may encounter returns without a preceeding call. This isn't an error, but we should pretend like the call started at the beginning of the profiling session:
171+
if (call == NULL) {
172+
struct IO_Event_Profiler_Call *last_call = IO_Event_Array_last(&profiler->calls);
173+
call = profiler_event_record_call(profiler, event_flag, id, klass);
174+
175+
if (last_call) {
176+
call->enter_time = last_call->enter_time;
177+
} else {
178+
call->enter_time = profiler->start_time;
179+
}
180+
}
156181

157182
IO_Event_Time_current(&call->exit_time);
158183

159184
profiler->current = call->parent;
160-
profiler->nesting -= 1;
185+
186+
// We may encounter returns without a preceeding call.
187+
if (profiler->nesting > 0)
188+
profiler->nesting -= 1;
161189
}
162190
}
163191

164-
void IO_Event_Profiler_restart(struct IO_Event_Profiler *profiler) {
192+
void IO_Event_Profiler_start(struct IO_Event_Profiler *profiler) {
193+
profiler->running = 1;
194+
165195
IO_Event_Time_current(&profiler->start_time);
166196

167197
profiler->nesting = 0;
168198
profiler->current = NULL;
169199

170-
IO_Event_Array_truncate(&profiler->calls, 0);
171-
}
172-
173-
void IO_Event_Profiler_start(struct IO_Event_Profiler *profiler) {
174-
if (DEBUG) fprintf(stderr, "Starting profiler (tracking calls: %d)\n", profiler->track_calls);
175-
176-
profiler->running = 1;
177-
178-
IO_Event_Profiler_restart(profiler);
179-
180200
// Since fibers are currently limited to a single thread, we use this in the hope that it's a little more efficient:
181201
if (profiler->track_calls) {
182202
VALUE thread = rb_thread_current();
183203
rb_thread_add_event_hook(thread, profiler_event_callback, RUBY_EVENT_CALL | RUBY_EVENT_C_CALL | RUBY_EVENT_RETURN | RUBY_EVENT_C_RETURN, profiler->self);
184204
}
185205
}
186206

187-
void IO_Event_Profiler_stop(struct IO_Event_Profiler *profiler) {
188-
if (DEBUG) fprintf(stderr, "Stopping profiler...\n");
189-
190-
profiler->running = 0;
191-
192-
if (profiler->track_calls) {
193-
VALUE thread = rb_thread_current();
194-
rb_thread_remove_event_hook_with_data(thread, profiler_event_callback, profiler->self);
195-
}
196-
}
197-
198207
static inline float IO_Event_Profiler_duration(struct IO_Event_Profiler *profiler) {
199208
struct timespec duration;
200209

201-
IO_Event_Time_elapsed(&profiler->start_time, &profiler->finish_time, &duration);
210+
IO_Event_Time_elapsed(&profiler->start_time, &profiler->stop_time, &duration);
202211

203212
return IO_Event_Time_duration(&duration);
204213
}
205214

206215
void IO_Event_Profiler_print(struct IO_Event_Profiler *profiler, FILE *restrict stream);
207216

208-
void IO_Event_Profile_finish(struct IO_Event_Profiler *profiler) {
209-
IO_Event_Time_current(&profiler->finish_time);
217+
void IO_Event_Profiler_stop(struct IO_Event_Profiler *profiler) {
218+
profiler->running = 0;
219+
220+
if (profiler->track_calls) {
221+
VALUE thread = rb_thread_current();
222+
rb_thread_remove_event_hook_with_data(thread, profiler_event_callback, profiler->self);
223+
}
210224

225+
IO_Event_Time_current(&profiler->stop_time);
211226
float duration = IO_Event_Profiler_duration(profiler);
212227

213228
if (duration > profiler->log_threshold) {
214229
IO_Event_Profiler_print(profiler, stderr);
215230
}
216231
}
217232

233+
void IO_Event_Profiler_restart(struct IO_Event_Profiler *profiler) {
234+
IO_Event_Profiler_stop(profiler);
235+
IO_Event_Array_truncate(&profiler->calls, 0);
236+
IO_Event_Profiler_start(profiler);
237+
}
238+
218239
VALUE IO_Event_Profiler_fiber_transfer(VALUE self, VALUE fiber, int argc, VALUE *argv) {
219240
struct IO_Event_Profiler *profiler = IO_Event_Profiler_get(self);
220241
int running = 0;
@@ -226,7 +247,6 @@ VALUE IO_Event_Profiler_fiber_transfer(VALUE self, VALUE fiber, int argc, VALUE
226247
running = profiler->running;
227248

228249
// We are switching to a different fiber, so consider the current profile complete:
229-
IO_Event_Profile_finish(profiler);
230250
IO_Event_Profiler_restart(profiler);
231251
}
232252

@@ -238,7 +258,6 @@ VALUE IO_Event_Profiler_fiber_transfer(VALUE self, VALUE fiber, int argc, VALUE
238258
IO_Event_Profiler_restart(profiler);
239259
} else {
240260
// Otherwise, we need to stop it:
241-
IO_Event_Profile_finish(profiler);
242261
IO_Event_Profiler_stop(profiler);
243262
}
244263

@@ -249,7 +268,7 @@ static const float IO_EVENT_PROFILER_PRINT_MINIMUM_PROPORTION = 0.01;
249268

250269
void IO_Event_Profiler_print_tty(struct IO_Event_Profiler *profiler, FILE *restrict stream) {
251270
struct timespec total_duration = {};
252-
IO_Event_Time_elapsed(&profiler->start_time, &profiler->finish_time, &total_duration);
271+
IO_Event_Time_elapsed(&profiler->start_time, &profiler->stop_time, &total_duration);
253272

254273
fprintf(stderr, "Fiber stalled for %.3f seconds\n", IO_Event_Time_duration(&total_duration));
255274

@@ -260,10 +279,13 @@ void IO_Event_Profiler_print_tty(struct IO_Event_Profiler *profiler, FILE *restr
260279
struct timespec duration = {};
261280
IO_Event_Time_elapsed(&call->enter_time, &call->exit_time, &duration);
262281

282+
const char *prefix = "";
283+
263284
// Skip calls that are too short to be meaningful:
264285
if (IO_Event_Time_proportion(&duration, &total_duration) < IO_EVENT_PROFILER_PRINT_MINIMUM_PROPORTION) {
265286
skipped += 1;
266287
continue;
288+
//prefix = "*";
267289
}
268290

269291
for (size_t i = 0; i < call->nesting; i += 1) {
@@ -273,7 +295,7 @@ void IO_Event_Profiler_print_tty(struct IO_Event_Profiler *profiler, FILE *restr
273295
VALUE class_inspect = rb_inspect(call->klass);
274296
const char *name = rb_id2name(call->id);
275297

276-
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));
298+
fprintf(stream, "%s%s:%d in %s '%s#%s' (" IO_EVENT_TIME_PRINTF_TIMESPEC "s)\n", prefix, call->path, call->line, event_flag_name(call->event_flag), RSTRING_PTR(class_inspect), name, IO_EVENT_TIME_PRINTF_TIMESPEC_ARGUMENTS(duration));
277299
}
278300

279301
if (skipped > 0) {
@@ -283,7 +305,7 @@ void IO_Event_Profiler_print_tty(struct IO_Event_Profiler *profiler, FILE *restr
283305

284306
void IO_Event_Profiler_print_json(struct IO_Event_Profiler *profiler, FILE *restrict stream) {
285307
struct timespec total_duration = {};
286-
IO_Event_Time_elapsed(&profiler->start_time, &profiler->finish_time, &total_duration);
308+
IO_Event_Time_elapsed(&profiler->start_time, &profiler->stop_time, &total_duration);
287309

288310
fputc('{', stream);
289311

‎ext/io/event/profiler.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ struct IO_Event_Profiler {
3434
int running;
3535

3636
struct timespec start_time;
37-
struct timespec finish_time;
37+
struct timespec stop_time;
3838

3939
// The depth of the call stack:
4040
size_t nesting;

0 commit comments

Comments
 (0)