22// Copyright, 2025, by Samuel Williams.
33
44#include "profiler.h"
5+
56#include "time.h"
67#include "fiber.h"
8+ #include "array.h"
79
810#include <ruby/debug.h>
9-
1011#include <stdio.h>
1112
12- static const int DEBUG = 0 ;
13-
1413VALUE IO_Event_Profiler = Qnil ;
1514
15+ struct IO_Event_Profiler_Call {
16+ struct timespec enter_time ;
17+ struct timespec exit_time ;
18+
19+ size_t nesting ;
20+
21+ rb_event_flag_t event_flag ;
22+ ID id ;
23+
24+ VALUE klass ;
25+ const char * path ;
26+ int line ;
27+
28+ struct IO_Event_Profiler_Call * parent ;
29+ };
30+
31+ struct IO_Event_Profiler {
32+ VALUE self ;
33+
34+ float log_threshold ;
35+ int track_calls ;
36+
37+ int running ;
38+
39+ // Whether or not to capture call data:
40+ int capture ;
41+
42+ // From this point on, the state of any profile in progress:
43+
44+ struct timespec start_time ;
45+ struct timespec stop_time ;
46+
47+ // The depth of the call stack:
48+ size_t nesting ;
49+
50+ // The current call frame:
51+ struct IO_Event_Profiler_Call * current ;
52+
53+ struct IO_Event_Array calls ;
54+ };
55+
1656void IO_Event_Profiler_Call_initialize (struct IO_Event_Profiler_Call * call ) {
1757 call -> enter_time .tv_sec = 0 ;
1858 call -> enter_time .tv_nsec = 0 ;
@@ -31,6 +71,7 @@ void IO_Event_Profiler_Call_initialize(struct IO_Event_Profiler_Call *call) {
3171void IO_Event_Profiler_Call_free (struct IO_Event_Profiler_Call * call ) {
3272 if (call -> path ) {
3373 free ((void * )call -> path );
74+ call -> path = NULL ;
3475 }
3576}
3677
@@ -81,10 +122,17 @@ const rb_data_type_t IO_Event_Profiler_Type = {
81122 .flags = RUBY_TYPED_FREE_IMMEDIATELY | RUBY_TYPED_WB_PROTECTED ,
82123};
83124
125+ struct IO_Event_Profiler * IO_Event_Profiler_get (VALUE self ) {
126+ struct IO_Event_Profiler * profiler ;
127+ TypedData_Get_Struct (self , struct IO_Event_Profiler , & IO_Event_Profiler_Type , profiler );
128+ return profiler ;
129+ }
130+
84131VALUE IO_Event_Profiler_allocate (VALUE klass ) {
85132 struct IO_Event_Profiler * profiler = ALLOC (struct IO_Event_Profiler );
86133
87134 profiler -> running = 0 ;
135+ profiler -> capture = 0 ;
88136
89137 profiler -> calls .element_initialize = (void (* )(void * ))IO_Event_Profiler_Call_initialize ;
90138 profiler -> calls .element_free = (void (* )(void * ))IO_Event_Profiler_Call_free ;
@@ -97,6 +145,57 @@ VALUE IO_Event_Profiler_allocate(VALUE klass) {
97145 return self ;
98146}
99147
148+ float IO_Event_Profiler_default_log_threshold () {
149+ const char * log_threshold = getenv ("IO_EVENT_PROFILER_DEFAULT_LOG_THRESHOLD" );
150+
151+ if (log_threshold ) {
152+ return strtof (log_threshold , NULL );
153+ } else {
154+ return 0.01 ;
155+ }
156+ }
157+
158+ int IO_Event_Profiler_default_track_calls () {
159+ const char * track_calls = getenv ("IO_EVENT_PROFILER_DEFAULT_TRACK_CALLS" );
160+
161+ if (track_calls ) {
162+ return atoi (track_calls );
163+ } else {
164+ return 1 ;
165+ }
166+ }
167+
168+ VALUE IO_Event_Profiler_initialize (int argc , VALUE * argv , VALUE self ) {
169+ struct IO_Event_Profiler * profiler = IO_Event_Profiler_get (self );
170+ VALUE log_threshold , track_calls ;
171+
172+ rb_scan_args (argc , argv , "02" , & log_threshold , & track_calls );
173+
174+ if (RB_NIL_P (log_threshold )) {
175+ profiler -> log_threshold = IO_Event_Profiler_default_log_threshold ();
176+ } else {
177+ profiler -> log_threshold = NUM2DBL (log_threshold );
178+ }
179+
180+ if (RB_NIL_P (track_calls )) {
181+ profiler -> track_calls = IO_Event_Profiler_default_track_calls ();
182+ } else {
183+ profiler -> track_calls = RB_TEST (track_calls );
184+ }
185+
186+ return self ;
187+ }
188+
189+ VALUE IO_Event_Profiler_default (VALUE klass ) {
190+ VALUE profiler = IO_Event_Profiler_allocate (klass );
191+
192+ struct IO_Event_Profiler * profiler_data = IO_Event_Profiler_get (profiler );
193+ profiler_data -> log_threshold = IO_Event_Profiler_default_log_threshold ();
194+ profiler_data -> track_calls = IO_Event_Profiler_default_track_calls ();
195+
196+ return profiler ;
197+ }
198+
100199VALUE IO_Event_Profiler_new (float log_threshold , int track_calls ) {
101200 VALUE profiler = IO_Event_Profiler_allocate (IO_Event_Profiler );
102201
@@ -107,12 +206,6 @@ VALUE IO_Event_Profiler_new(float log_threshold, int track_calls) {
107206 return profiler ;
108207}
109208
110- struct IO_Event_Profiler * IO_Event_Profiler_get (VALUE self ) {
111- struct IO_Event_Profiler * profiler ;
112- TypedData_Get_Struct (self , struct IO_Event_Profiler , & IO_Event_Profiler_Type , profiler );
113- return profiler ;
114- }
115-
116209int event_flag_call_p (rb_event_flag_t event_flags ) {
117210 return event_flags & (RUBY_EVENT_CALL | RUBY_EVENT_C_CALL );
118211}
@@ -158,13 +251,25 @@ static struct IO_Event_Profiler_Call* profiler_event_record_call(struct IO_Event
158251 return call ;
159252}
160253
161- static void profiler_event_callback (rb_event_flag_t event_flag , VALUE data , VALUE self , ID id , VALUE klass ) {
254+ void IO_Event_Profiler_fiber_switch (struct IO_Event_Profiler * profiler );
255+
256+ static void IO_Event_Profiler_callback (rb_event_flag_t event_flag , VALUE data , VALUE self , ID id , VALUE klass ) {
162257 struct IO_Event_Profiler * profiler = IO_Event_Profiler_get (data );
163258
259+ if (event_flag == RUBY_EVENT_FIBER_SWITCH ) {
260+ IO_Event_Profiler_fiber_switch (profiler );
261+ return ;
262+ }
263+
264+ // We don't want to capture data if we're not running:
265+ if (!profiler -> running ) return ;
266+
164267 if (event_flag_call_p (event_flag )) {
165268 struct IO_Event_Profiler_Call * call = profiler_event_record_call (profiler , event_flag , id , klass );
166269 IO_Event_Time_current (& call -> enter_time );
167- } else if (event_flag_return_p (event_flag )) {
270+ }
271+
272+ else if (event_flag_return_p (event_flag )) {
168273 struct IO_Event_Profiler_Call * call = profiler -> current ;
169274
170275 // 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:
@@ -189,79 +294,71 @@ static void profiler_event_callback(rb_event_flag_t event_flag, VALUE data, VALU
189294 }
190295}
191296
192- void IO_Event_Profiler_start (struct IO_Event_Profiler * profiler ) {
193- profiler -> running = 1 ;
297+ VALUE IO_Event_Profiler_start (VALUE self ) {
298+ struct IO_Event_Profiler * profiler = IO_Event_Profiler_get ( self ) ;
194299
195- IO_Event_Time_current ( & profiler -> start_time ) ;
300+ if ( profiler -> running ) return Qfalse ;
196301
197- profiler -> nesting = 0 ;
198- profiler -> current = NULL ;
302+ profiler -> running = 1 ;
199303
200- // Since fibers are currently limited to a single thread, we use this in the hope that it's a little more efficient:
304+ rb_event_flag_t event_flags = RUBY_EVENT_FIBER_SWITCH ;
201305 if (profiler -> track_calls ) {
202- VALUE thread = rb_thread_current ();
203- 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 );
306+ event_flags |= RUBY_EVENT_CALL | RUBY_EVENT_C_CALL | RUBY_EVENT_RETURN | RUBY_EVENT_C_RETURN ;
204307 }
308+
309+ VALUE thread = rb_thread_current ();
310+ rb_thread_add_event_hook (thread , IO_Event_Profiler_callback , event_flags , profiler -> self );
311+
312+ return self ;
313+ }
314+
315+ VALUE IO_Event_Profiler_stop (VALUE self ) {
316+ struct IO_Event_Profiler * profiler = IO_Event_Profiler_get (self );
317+
318+ if (!profiler -> running ) return Qfalse ;
319+
320+ profiler -> running = 0 ;
321+
322+ VALUE thread = rb_thread_current ();
323+ rb_thread_remove_event_hook_with_data (thread , IO_Event_Profiler_callback , profiler -> self );
324+
325+ return self ;
205326}
206327
207328static inline float IO_Event_Profiler_duration (struct IO_Event_Profiler * profiler ) {
208329 struct timespec duration ;
209330
331+ IO_Event_Time_current (& profiler -> stop_time );
210332 IO_Event_Time_elapsed (& profiler -> start_time , & profiler -> stop_time , & duration );
211333
212334 return IO_Event_Time_duration (& duration );
213335}
214336
215337void IO_Event_Profiler_print (struct IO_Event_Profiler * profiler , FILE * restrict stream );
216338
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- }
224-
225- IO_Event_Time_current (& profiler -> stop_time );
339+ void IO_Event_Profiler_fiber_switch (struct IO_Event_Profiler * profiler )
340+ {
226341 float duration = IO_Event_Profiler_duration (profiler );
227342
228- if (duration > profiler -> log_threshold ) {
229- IO_Event_Profiler_print (profiler , stderr );
230- }
231- }
232-
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-
239- VALUE IO_Event_Profiler_fiber_transfer (VALUE self , VALUE fiber , int argc , VALUE * argv ) {
240- struct IO_Event_Profiler * profiler = IO_Event_Profiler_get (self );
241- int running = 0 ;
242-
243- // If we are running when we enter, that means we are currently profiling, and we need to restart the profiler when we exit:
244- if (!profiler -> running ) {
245- IO_Event_Profiler_start (profiler );
246- } else {
247- running = profiler -> running ;
343+ if (profiler -> capture ) {
344+ profiler -> capture = 0 ;
248345
249- // We are switching to a different fiber, so consider the current profile complete:
250- IO_Event_Profiler_restart (profiler );
346+ if (duration > profiler -> log_threshold ) {
347+ IO_Event_Profiler_print (profiler , stderr );
348+ }
349+
350+ // Clear the profile state:
351+ profiler -> nesting = 0 ;
352+ profiler -> current = NULL ;
353+ IO_Event_Array_truncate (& profiler -> calls , 0 );
251354 }
252355
253- if (DEBUG ) fprintf (stderr , "Transferring to fiber %p\n" , (void * )fiber );
254- VALUE result = IO_Event_Fiber_transfer (fiber , argc , argv );
255-
256- if (running ) {
257- // If the profiler was running, we need to restart it:
258- IO_Event_Profiler_restart (profiler );
259- } else {
260- // Otherwise, we need to stop it:
261- IO_Event_Profiler_stop (profiler );
356+ if (!IO_Event_Fiber_blocking (IO_Event_Fiber_current ())) {
357+ profiler -> capture = 1 ;
358+
359+ // Reset the start time:
360+ IO_Event_Time_current (& profiler -> start_time );
262361 }
263-
264- return result ;
265362}
266363
267364static const float IO_EVENT_PROFILER_PRINT_MINIMUM_PROPORTION = 0.01 ;
@@ -355,4 +452,11 @@ void IO_Event_Profiler_print(struct IO_Event_Profiler *profiler, FILE *restrict
355452void Init_IO_Event_Profiler (VALUE IO_Event ) {
356453 IO_Event_Profiler = rb_define_class_under (IO_Event , "Profiler" , rb_cObject );
357454 rb_define_alloc_func (IO_Event_Profiler , IO_Event_Profiler_allocate );
455+
456+ rb_define_singleton_method (IO_Event_Profiler , "default" , IO_Event_Profiler_default , 0 );
457+
458+ rb_define_method (IO_Event_Profiler , "initialize" , IO_Event_Profiler_initialize , -1 );
459+
460+ rb_define_method (IO_Event_Profiler , "start" , IO_Event_Profiler_start , 0 );
461+ rb_define_method (IO_Event_Profiler , "stop" , IO_Event_Profiler_stop , 0 );
358462}
0 commit comments