From 39d345b365d5f2bc2eddbeba1b215056b2206605 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 11:47:37 -0800 Subject: [PATCH 01/20] WIP --- ext/stackprof/stackprof.c | 44 +++++++++++++++++++++++++++++++++++---- 1 file changed, 40 insertions(+), 4 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index ae3467d4..e970552d 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -33,6 +33,7 @@ static struct { VALUE mode; VALUE interval; VALUE out; + VALUE detect_hung; VALUE *raw_samples; size_t raw_samples_len; @@ -60,6 +61,7 @@ static struct { static VALUE sym_object, sym_wall, sym_cpu, sym_custom, sym_name, sym_file, sym_line; static VALUE sym_samples, sym_total_samples, sym_missed_samples, sym_edges, sym_lines; static VALUE sym_version, sym_mode, sym_interval, sym_raw, sym_frames, sym_out, sym_aggregate, sym_raw_timestamp_deltas; +static VALUE sym_detect_hung; static VALUE sym_gc_samples, objtracer; static VALUE gc_hook; static VALUE rb_mStackProf; @@ -72,7 +74,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) { struct sigaction sa; struct itimerval timer; - VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse; + VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse, detect_hung = Qfalse; int raw = 0, aggregate = 1; if (_stackprof.running) @@ -84,6 +86,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) mode = rb_hash_aref(opts, sym_mode); interval = rb_hash_aref(opts, sym_interval); out = rb_hash_aref(opts, sym_out); + detect_hung = rb_hash_aref(opts, sym_detect_hung); if (RTEST(rb_hash_aref(opts, sym_raw))) raw = 1; @@ -99,6 +102,11 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.during_gc = 0; } + if (detect_hung == Qtrue && mode != sym_wall) { + rb_raise(rb_eNotImpError, "`detect_hung` is only implemented for `wall` mode (EXPERIMENTAL)"); + } + _stackprof.detect_hung = detect_hung; + if (mode == sym_object) { if (!RTEST(interval)) interval = INT2FIX(1); @@ -383,6 +391,11 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) int i, n; VALUE prev_frame = Qnil; + struct timeval sample_start, sample_finish; + struct timeval sample_duration_tdif; + int sample_duration_usec; + gettimeofday(&sample_start, NULL); + _stackprof.overall_samples++; if (_stackprof.raw) { @@ -482,8 +495,23 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) prev_frame = frame; } + gettimeofday(&sample_finish, NULL); + if (_stackprof.raw) { - gettimeofday(&_stackprof.last_sample_at, NULL); + _stackprof.last_sample_at = sample_finish; + } + + // [EXPERIMENTAL] Protect against individual samples taking longer to capture than the interval between samples, + // which will cause the sampling to pile up infinitely, peg the CPU, and hang the program. + if (RTEST(_stackprof.detect_hung)) { + timersub(&sample_finish, &sample_start, &sample_duration_tdif); + sample_duration_usec = stackprof_timeval_to_usec(&sample_duration_tdif); + if (sample_duration_usec >= FIX2INT(_stackprof.interval)) { + fprintf(stderr, "\nUH OH TOO LONG: %d with interval %d\n", sample_duration_usec, FIX2INT(_stackprof.interval)); + + // TODO insert some kind of fake frame? + // or skip next frame? + } } } @@ -497,7 +525,7 @@ stackprof_record_sample() struct timeval diff; gettimeofday(&t, NULL); timersub(&t, &_stackprof.last_sample_at, &diff); - timestamp_delta = (1000 * diff.tv_sec) + diff.tv_usec; + timestamp_delta = stackprof_timeval_to_usec(&diff); } num = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); stackprof_record_sample_for_stack(num, timestamp_delta); @@ -516,7 +544,7 @@ stackprof_record_gc_samples() // We don't know when the GC samples were actually marked, so let's // assume that they were marked at a perfectly regular interval. - delta_to_first_unrecorded_gc_sample = (1000 * diff.tv_sec + diff.tv_usec) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); + delta_to_first_unrecorded_gc_sample = stackprof_timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); if (delta_to_first_unrecorded_gc_sample < 0) { delta_to_first_unrecorded_gc_sample = 0; } @@ -639,6 +667,11 @@ stackprof_atfork_child(void) stackprof_stop(rb_mStackProf); } +int +stackprof_timeval_to_usec(struct timeval *diff) { + return MICROSECONDS_IN_SECOND * diff->tv_sec + diff->tv_usec; +} + void Init_stackprof(void) { @@ -664,6 +697,7 @@ Init_stackprof(void) S(out); S(frames); S(aggregate); + S(detect_hung); #undef S gc_hook = Data_Wrap_Struct(rb_cObject, stackprof_gc_mark, NULL, &_stackprof); @@ -678,6 +712,8 @@ Init_stackprof(void) _stackprof.raw_timestamp_deltas_len = 0; _stackprof.raw_timestamp_deltas_capa = 0; + // TODO(benbuckman) can we do a similar fake frame when sampling rate is too fast? + _stackprof.fake_gc_frame = INT2FIX(0x9C); _stackprof.empty_string = rb_str_new_cstr(""); _stackprof.fake_gc_frame_name = rb_str_new_cstr("(garbage collection)"); From e8f7e50f00c913b32aaa60dba96454cecfa1f980 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 14:13:29 -0800 Subject: [PATCH 02/20] `num` -> `frame_count` --- ext/stackprof/stackprof.c | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index e970552d..028052c7 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -386,7 +386,7 @@ st_numtable_increment(st_table *table, st_data_t key, size_t increment) } void -stackprof_record_sample_for_stack(int num, int timestamp_delta) +stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) { int i, n; VALUE prev_frame = Qnil; @@ -402,29 +402,29 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) int found = 0; /* If there's no sample buffer allocated, then allocate one. The buffer - * format is the number of frames (num), then the list of frames (from + * format is the number of frames (frame_count), then the list of frames (from * `_stackprof.raw_samples`), followed by the number of times this * particular stack has been seen in a row. Each "new" stack is added * to the end of the buffer, but if the previous stack is the same as * the current stack, the counter will be incremented. */ if (!_stackprof.raw_samples) { - _stackprof.raw_samples_capa = num * 100; + _stackprof.raw_samples_capa = frame_count * 100; _stackprof.raw_samples = malloc(sizeof(VALUE) * _stackprof.raw_samples_capa); } /* If we can't fit all the samples in the buffer, double the buffer size. */ - while (_stackprof.raw_samples_capa <= _stackprof.raw_samples_len + (num + 2)) { + while (_stackprof.raw_samples_capa <= _stackprof.raw_samples_len + (frame_count + 2)) { _stackprof.raw_samples_capa *= 2; _stackprof.raw_samples = realloc(_stackprof.raw_samples, sizeof(VALUE) * _stackprof.raw_samples_capa); } /* If we've seen this stack before in the last sample, then increment the "seen" count. */ - if (_stackprof.raw_samples_len > 0 && _stackprof.raw_samples[_stackprof.raw_sample_index] == (VALUE)num) { + if (_stackprof.raw_samples_len > 0 && _stackprof.raw_samples[_stackprof.raw_sample_index] == (VALUE)frame_count) { /* The number of samples could have been the same, but the stack * might be different, so we need to check the stack here. Stacks * in the raw buffer are stored in the opposite direction of stacks * in the frames buffer that came from Ruby. */ - for (i = num-1, n = 0; i >= 0; i--, n++) { + for (i = frame_count-1, n = 0; i >= 0; i--, n++) { VALUE frame = _stackprof.frames_buffer[i]; if (_stackprof.raw_samples[_stackprof.raw_sample_index + 1 + n] != frame) break; @@ -441,8 +441,8 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) /* Bump the `raw_sample_index` up so that the next iteration can * find the previously recorded stack size. */ _stackprof.raw_sample_index = _stackprof.raw_samples_len; - _stackprof.raw_samples[_stackprof.raw_samples_len++] = (VALUE)num; - for (i = num-1; i >= 0; i--) { + _stackprof.raw_samples[_stackprof.raw_samples_len++] = (VALUE)frame_count; + for (i = frame_count-1; i >= 0; i--) { VALUE frame = _stackprof.frames_buffer[i]; _stackprof.raw_samples[_stackprof.raw_samples_len++] = frame; } @@ -466,7 +466,7 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) _stackprof.raw_timestamp_deltas[_stackprof.raw_timestamp_deltas_len++] = timestamp_delta; } - for (i = 0; i < num; i++) { + for (i = 0; i < frame_count; i++) { int line = _stackprof.lines_buffer[i]; VALUE frame = _stackprof.frames_buffer[i]; frame_data_t *frame_data = sample_for(frame); @@ -519,7 +519,7 @@ void stackprof_record_sample() { int timestamp_delta = 0; - int num; + int frame_count; if (_stackprof.raw) { struct timeval t; struct timeval diff; @@ -527,8 +527,8 @@ stackprof_record_sample() timersub(&t, &_stackprof.last_sample_at, &diff); timestamp_delta = stackprof_timeval_to_usec(&diff); } - num = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); - stackprof_record_sample_for_stack(num, timestamp_delta); + frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); + stackprof_record_sample_for_stack(frame_count, timestamp_delta); } void From ce003df848f18d36a19d612d4cf99951b8bca870 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 14:21:40 -0800 Subject: [PATCH 03/20] comment on `stackprof_record_sample_for_stack` --- ext/stackprof/stackprof.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 028052c7..1076f0f1 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -385,6 +385,11 @@ st_numtable_increment(st_table *table, st_data_t key, size_t increment) st_update(table, key, numtable_increment_callback, (st_data_t)increment); } +/* + Records information about the frames captured in `_stackprof.frames_buffer`, + up to `frame_count-1` (buffer may contain more frames from prior sample), + captured `timestamp_delta` microseconds after previous sample. +*/ void stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) { From bbdbcbbb3d08b5e0d41d55e9d2252dabc2c92ea9 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 14:28:43 -0800 Subject: [PATCH 04/20] WIP always capture timeofday, last_sample_at --- ext/stackprof/stackprof.c | 31 +++++++++++++------------------ 1 file changed, 13 insertions(+), 18 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 1076f0f1..20a70ac1 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -138,9 +138,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.interval = interval; _stackprof.out = out; - if (raw) { - gettimeofday(&_stackprof.last_sample_at, NULL); - } + gettimeofday(&_stackprof.last_sample_at, NULL); return Qtrue; } @@ -500,11 +498,7 @@ stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) prev_frame = frame; } - gettimeofday(&sample_finish, NULL); - - if (_stackprof.raw) { - _stackprof.last_sample_at = sample_finish; - } + gettimeofday(&_stackprof.last_sample_at, NULL); // [EXPERIMENTAL] Protect against individual samples taking longer to capture than the interval between samples, // which will cause the sampling to pile up infinitely, peg the CPU, and hang the program. @@ -525,12 +519,13 @@ stackprof_record_sample() { int timestamp_delta = 0; int frame_count; + struct timeval t; + struct timeval time_since_last_sample; + gettimeofday(&t, NULL); + timersub(&t, &_stackprof.last_sample_at, &time_since_last_sample); + if (_stackprof.raw) { - struct timeval t; - struct timeval diff; - gettimeofday(&t, NULL); - timersub(&t, &_stackprof.last_sample_at, &diff); - timestamp_delta = stackprof_timeval_to_usec(&diff); + timestamp_delta = stackprof_timeval_to_usec(&time_since_last_sample); } frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); stackprof_record_sample_for_stack(frame_count, timestamp_delta); @@ -541,12 +536,12 @@ stackprof_record_gc_samples() { int delta_to_first_unrecorded_gc_sample = 0; int i; - if (_stackprof.raw) { - struct timeval t; - struct timeval diff; - gettimeofday(&t, NULL); - timersub(&t, &_stackprof.last_sample_at, &diff); + struct timeval t; + struct timeval diff; + gettimeofday(&t, NULL); + timersub(&t, &_stackprof.last_sample_at, &diff); + if (_stackprof.raw) { // We don't know when the GC samples were actually marked, so let's // assume that they were marked at a perfectly regular interval. delta_to_first_unrecorded_gc_sample = stackprof_timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); From 1d4da7bc4c1761d4cee745b85d26471791c07f1c Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 18:54:10 -0800 Subject: [PATCH 05/20] WIP - measuring correctly in `stackprof_record_sample` --- ext/stackprof/stackprof.c | 68 ++++++++++++++++++++++----------------- 1 file changed, 39 insertions(+), 29 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 20a70ac1..00c9e2dc 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -68,6 +68,8 @@ static VALUE rb_mStackProf; static void stackprof_newobj_handler(VALUE, void*); static void stackprof_signal_handler(int sig, siginfo_t* sinfo, void* ucontext); +long int timeval_to_usec(struct timeval *diff); +long int diff_timevals_usec(struct timeval *start, struct timeval *end); static VALUE stackprof_start(int argc, VALUE *argv, VALUE self) @@ -394,11 +396,6 @@ stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) int i, n; VALUE prev_frame = Qnil; - struct timeval sample_start, sample_finish; - struct timeval sample_duration_tdif; - int sample_duration_usec; - gettimeofday(&sample_start, NULL); - _stackprof.overall_samples++; if (_stackprof.raw) { @@ -499,14 +496,33 @@ stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) } gettimeofday(&_stackprof.last_sample_at, NULL); +} + +void +stackprof_record_sample() +{ + int frame_count; + struct timeval sampling_start, sampling_finish; + + gettimeofday(&sampling_start, NULL); + long int time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); + + fprintf(stderr, "timestamp delta %ld usec since last with interval %ld\n", time_since_last_sample_usec, NUM2LONG(_stackprof.interval)); + + frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); + + stackprof_record_sample_for_stack(frame_count, time_since_last_sample_usec); + + gettimeofday(&sampling_finish, NULL); + _stackprof.last_sample_at = sampling_finish; // [EXPERIMENTAL] Protect against individual samples taking longer to capture than the interval between samples, // which will cause the sampling to pile up infinitely, peg the CPU, and hang the program. if (RTEST(_stackprof.detect_hung)) { - timersub(&sample_finish, &sample_start, &sample_duration_tdif); - sample_duration_usec = stackprof_timeval_to_usec(&sample_duration_tdif); - if (sample_duration_usec >= FIX2INT(_stackprof.interval)) { - fprintf(stderr, "\nUH OH TOO LONG: %d with interval %d\n", sample_duration_usec, FIX2INT(_stackprof.interval)); + long int sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); + fprintf(stderr, "CHECK: time to stackprof_record_sample_for_stack: %ld usec\n", sampling_duration_usec); + if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { + fprintf(stderr, "\nUH OH TOO LONG: %d with interval %d\n", sampling_duration_usec, NUM2LONG(_stackprof.interval)); // TODO insert some kind of fake frame? // or skip next frame? @@ -514,23 +530,6 @@ stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) } } -void -stackprof_record_sample() -{ - int timestamp_delta = 0; - int frame_count; - struct timeval t; - struct timeval time_since_last_sample; - gettimeofday(&t, NULL); - timersub(&t, &_stackprof.last_sample_at, &time_since_last_sample); - - if (_stackprof.raw) { - timestamp_delta = stackprof_timeval_to_usec(&time_since_last_sample); - } - frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); - stackprof_record_sample_for_stack(frame_count, timestamp_delta); -} - void stackprof_record_gc_samples() { @@ -544,7 +543,7 @@ stackprof_record_gc_samples() if (_stackprof.raw) { // We don't know when the GC samples were actually marked, so let's // assume that they were marked at a perfectly regular interval. - delta_to_first_unrecorded_gc_sample = stackprof_timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); + delta_to_first_unrecorded_gc_sample = timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); if (delta_to_first_unrecorded_gc_sample < 0) { delta_to_first_unrecorded_gc_sample = 0; } @@ -667,11 +666,22 @@ stackprof_atfork_child(void) stackprof_stop(rb_mStackProf); } -int -stackprof_timeval_to_usec(struct timeval *diff) { +long int timeval_to_usec(struct timeval *diff) { return MICROSECONDS_IN_SECOND * diff->tv_sec + diff->tv_usec; } +long int diff_timevals_usec(struct timeval *start, struct timeval *end) { + struct timeval diff; + if ((end->tv_usec - start->tv_usec) < 0) { + diff.tv_sec = end->tv_sec - start->tv_sec - 1; + diff.tv_usec = MICROSECONDS_IN_SECOND + end->tv_usec - start->tv_usec; + } else { + diff.tv_sec = end->tv_sec - start->tv_sec; + diff.tv_usec = end->tv_usec - start->tv_usec; + } + return timeval_to_usec(&diff); +} + void Init_stackprof(void) { From 5bb43e321e2084853282414ee0365725de2150f9 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 23:33:22 -0800 Subject: [PATCH 06/20] move `in_signal_handler` lock to global struct, checked in signal handler --- ext/stackprof/stackprof.c | 38 +++++++++++++++++++++++++++----------- 1 file changed, 27 insertions(+), 11 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 00c9e2dc..453b64db 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -29,6 +29,7 @@ static struct { int running; int raw; int aggregate; + int in_signal_handler; VALUE mode; VALUE interval; @@ -40,6 +41,7 @@ static struct { size_t raw_samples_capa; size_t raw_sample_index; + struct timeval started_at; struct timeval last_sample_at; int *raw_timestamp_deltas; size_t raw_timestamp_deltas_len; @@ -139,8 +141,10 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.mode = mode; _stackprof.interval = interval; _stackprof.out = out; + _stackprof.in_signal_handler = 0; - gettimeofday(&_stackprof.last_sample_at, NULL); + gettimeofday(&_stackprof.started_at, NULL); + _stackprof.last_sample_at = _stackprof.started_at; return Qtrue; } @@ -165,6 +169,7 @@ stackprof_stop(VALUE self) sa.sa_flags = SA_RESTART; sigemptyset(&sa.sa_mask); sigaction(_stackprof.mode == sym_wall ? SIGALRM : SIGPROF, &sa, NULL); + _stackprof.in_signal_handler = 0; } else if (_stackprof.mode == sym_custom) { /* sampled manually */ } else { @@ -506,8 +511,12 @@ stackprof_record_sample() gettimeofday(&sampling_start, NULL); long int time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); + long int time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); - fprintf(stderr, "timestamp delta %ld usec since last with interval %ld\n", time_since_last_sample_usec, NUM2LONG(_stackprof.interval)); + fprintf(stderr, "timestamp delta %ld usec since last, %ld since start, with interval %ld\n", + time_since_last_sample_usec, + time_since_start_usec, + NUM2LONG(_stackprof.interval)); frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); @@ -520,7 +529,10 @@ stackprof_record_sample() // which will cause the sampling to pile up infinitely, peg the CPU, and hang the program. if (RTEST(_stackprof.detect_hung)) { long int sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); - fprintf(stderr, "CHECK: time to stackprof_record_sample_for_stack: %ld usec\n", sampling_duration_usec); + fprintf(stderr, "duration of stackprof_record_sample: %ld usec with interval %d\n", + sampling_duration_usec, + NUM2LONG(_stackprof.interval)); + if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { fprintf(stderr, "\nUH OH TOO LONG: %d with interval %d\n", sampling_duration_usec, NUM2LONG(_stackprof.interval)); @@ -563,31 +575,35 @@ stackprof_record_gc_samples() static void stackprof_gc_job_handler(void *data) { - static int in_signal_handler = 0; - if (in_signal_handler) return; + if (_stackprof.in_signal_handler) return; if (!_stackprof.running) return; - in_signal_handler++; + _stackprof.in_signal_handler++; stackprof_record_gc_samples(); - in_signal_handler--; + _stackprof.in_signal_handler--; } static void stackprof_job_handler(void *data) { - static int in_signal_handler = 0; - if (in_signal_handler) return; + if (_stackprof.in_signal_handler) return; if (!_stackprof.running) return; - in_signal_handler++; + _stackprof.in_signal_handler++; stackprof_record_sample(); - in_signal_handler--; + _stackprof.in_signal_handler--; } static void stackprof_signal_handler(int sig, siginfo_t *sinfo, void *ucontext) { _stackprof.overall_signals++; + + if (_stackprof.in_signal_handler) { + fprintf(stderr, "skip stackprof_signal_handler, already in handler\n"); + return; + } + if (rb_during_gc()) { _stackprof.unrecorded_gc_samples++; rb_postponed_job_register_one(0, stackprof_gc_job_handler, (void*)0); From 9ce3a2f98dd77e29c502a6fc8ffdaf2062f7be43 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Wed, 6 Nov 2019 23:52:43 -0800 Subject: [PATCH 07/20] `debug` mode --- ext/stackprof/stackprof.c | 50 +++++++++++++++++++-------------------- test/test_stackprof.rb | 19 +++++++++++++++ 2 files changed, 43 insertions(+), 26 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 453b64db..8163854d 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -34,7 +34,7 @@ static struct { VALUE mode; VALUE interval; VALUE out; - VALUE detect_hung; + VALUE debug; VALUE *raw_samples; size_t raw_samples_len; @@ -63,7 +63,7 @@ static struct { static VALUE sym_object, sym_wall, sym_cpu, sym_custom, sym_name, sym_file, sym_line; static VALUE sym_samples, sym_total_samples, sym_missed_samples, sym_edges, sym_lines; static VALUE sym_version, sym_mode, sym_interval, sym_raw, sym_frames, sym_out, sym_aggregate, sym_raw_timestamp_deltas; -static VALUE sym_detect_hung; +static VALUE sym_debug; static VALUE sym_gc_samples, objtracer; static VALUE gc_hook; static VALUE rb_mStackProf; @@ -78,7 +78,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) { struct sigaction sa; struct itimerval timer; - VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse, detect_hung = Qfalse; + VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse, debug = Qfalse; int raw = 0, aggregate = 1; if (_stackprof.running) @@ -90,13 +90,15 @@ stackprof_start(int argc, VALUE *argv, VALUE self) mode = rb_hash_aref(opts, sym_mode); interval = rb_hash_aref(opts, sym_interval); out = rb_hash_aref(opts, sym_out); - detect_hung = rb_hash_aref(opts, sym_detect_hung); + debug = rb_hash_aref(opts, sym_debug); if (RTEST(rb_hash_aref(opts, sym_raw))) raw = 1; if (rb_hash_lookup2(opts, sym_aggregate, Qundef) == Qfalse) aggregate = 0; } + _stackprof.debug = RTEST(debug); + if (!RTEST(mode)) mode = sym_wall; if (!_stackprof.frames) { @@ -106,11 +108,6 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.during_gc = 0; } - if (detect_hung == Qtrue && mode != sym_wall) { - rb_raise(rb_eNotImpError, "`detect_hung` is only implemented for `wall` mode (EXPERIMENTAL)"); - } - _stackprof.detect_hung = detect_hung; - if (mode == sym_object) { if (!RTEST(interval)) interval = INT2FIX(1); @@ -511,12 +508,14 @@ stackprof_record_sample() gettimeofday(&sampling_start, NULL); long int time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); - long int time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); - fprintf(stderr, "timestamp delta %ld usec since last, %ld since start, with interval %ld\n", - time_since_last_sample_usec, - time_since_start_usec, - NUM2LONG(_stackprof.interval)); + if (_stackprof.debug) { + long int time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); + printf("timestamp delta %ld usec since last, %ld since start, with interval %ld\n", + time_since_last_sample_usec, + time_since_start_usec, + NUM2LONG(_stackprof.interval)); + } frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); @@ -525,19 +524,16 @@ stackprof_record_sample() gettimeofday(&sampling_finish, NULL); _stackprof.last_sample_at = sampling_finish; - // [EXPERIMENTAL] Protect against individual samples taking longer to capture than the interval between samples, - // which will cause the sampling to pile up infinitely, peg the CPU, and hang the program. - if (RTEST(_stackprof.detect_hung)) { + if (_stackprof.debug) { long int sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); - fprintf(stderr, "duration of stackprof_record_sample: %ld usec with interval %d\n", + printf("duration of stackprof_record_sample: %ld usec with interval %d\n", sampling_duration_usec, NUM2LONG(_stackprof.interval)); if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { - fprintf(stderr, "\nUH OH TOO LONG: %d with interval %d\n", sampling_duration_usec, NUM2LONG(_stackprof.interval)); - - // TODO insert some kind of fake frame? - // or skip next frame? + fprintf(stderr, "INTERVAL IS TOO FAST: %d with interval %d\n", + sampling_duration_usec, + NUM2LONG(_stackprof.interval)); } } } @@ -599,8 +595,12 @@ stackprof_signal_handler(int sig, siginfo_t *sinfo, void *ucontext) { _stackprof.overall_signals++; + // Protect against individual samples taking longer to capture than + // the interval between samples, which would cause the job queue + // to pile up faster than it's flushed, peg the CPU, and hang the program. if (_stackprof.in_signal_handler) { - fprintf(stderr, "skip stackprof_signal_handler, already in handler\n"); + if (_stackprof.debug) + fprintf(stderr, "skip stackprof_signal_handler, already in handler!\n"); return; } @@ -723,7 +723,7 @@ Init_stackprof(void) S(out); S(frames); S(aggregate); - S(detect_hung); + S(debug); #undef S gc_hook = Data_Wrap_Struct(rb_cObject, stackprof_gc_mark, NULL, &_stackprof); @@ -738,8 +738,6 @@ Init_stackprof(void) _stackprof.raw_timestamp_deltas_len = 0; _stackprof.raw_timestamp_deltas_capa = 0; - // TODO(benbuckman) can we do a similar fake frame when sampling rate is too fast? - _stackprof.fake_gc_frame = INT2FIX(0x9C); _stackprof.empty_string = rb_str_new_cstr(""); _stackprof.fake_gc_frame_name = rb_str_new_cstr("(garbage collection)"); diff --git a/test/test_stackprof.rb b/test/test_stackprof.rb index 27da5c37..0ae0712d 100644 --- a/test/test_stackprof.rb +++ b/test/test_stackprof.rb @@ -3,6 +3,7 @@ require 'minitest/autorun' require 'tempfile' require 'pathname' +require 'timeout' class StackProfTest < MiniTest::Test def test_info @@ -194,6 +195,16 @@ def test_pathname_out refute_empty profile[:frames] end + def test_wall_too_fast_no_hang + # The stack of `recurse` takes longer than 10μs to sample, + # so if this was not handled properly, the job queue would pile up + # faster than it was flushed, and the program would hang. + # Timeout ensures that if this is broken, the test itself does not hang. + Timeout.timeout(10) do + StackProf.run(mode: :wall, interval: 10) { recurse } + end + end + def math 250_000.times do 2 ** 10 @@ -207,4 +218,12 @@ def idle r.close w.close end + + def recurse(num = 1, depth = 1) + if depth == 10000 + num + else + recurse(num * 2, depth + 1) + end + end end From 2d3e274407a3b6fbc341cb67d291e39ea1e173b4 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Fri, 8 Nov 2019 13:21:53 -0800 Subject: [PATCH 08/20] use `int64_t` instead of `long int` --- ext/stackprof/stackprof.c | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 8163854d..4f6ef2e5 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -14,6 +14,7 @@ #include #include #include +#include #define BUF_SIZE 2048 @@ -70,8 +71,8 @@ static VALUE rb_mStackProf; static void stackprof_newobj_handler(VALUE, void*); static void stackprof_signal_handler(int sig, siginfo_t* sinfo, void* ucontext); -long int timeval_to_usec(struct timeval *diff); -long int diff_timevals_usec(struct timeval *start, struct timeval *end); +int64_t timeval_to_usec(struct timeval *diff); +int64_t diff_timevals_usec(struct timeval *start, struct timeval *end); static VALUE stackprof_start(int argc, VALUE *argv, VALUE self) @@ -507,10 +508,10 @@ stackprof_record_sample() struct timeval sampling_start, sampling_finish; gettimeofday(&sampling_start, NULL); - long int time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); + int64_t time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); if (_stackprof.debug) { - long int time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); + int64_t time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); printf("timestamp delta %ld usec since last, %ld since start, with interval %ld\n", time_since_last_sample_usec, time_since_start_usec, @@ -525,7 +526,7 @@ stackprof_record_sample() _stackprof.last_sample_at = sampling_finish; if (_stackprof.debug) { - long int sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); + int64_t sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); printf("duration of stackprof_record_sample: %ld usec with interval %d\n", sampling_duration_usec, NUM2LONG(_stackprof.interval)); @@ -682,11 +683,11 @@ stackprof_atfork_child(void) stackprof_stop(rb_mStackProf); } -long int timeval_to_usec(struct timeval *diff) { +int64_t timeval_to_usec(struct timeval *diff) { return MICROSECONDS_IN_SECOND * diff->tv_sec + diff->tv_usec; } -long int diff_timevals_usec(struct timeval *start, struct timeval *end) { +int64_t diff_timevals_usec(struct timeval *start, struct timeval *end) { struct timeval diff; if ((end->tv_usec - start->tv_usec) < 0) { diff.tv_sec = end->tv_sec - start->tv_sec - 1; From d250bd4f19d3763f1eb09de904d630fde2be232f Mon Sep 17 00:00:00 2001 From: benbuckman Date: Fri, 8 Nov 2019 13:23:33 -0800 Subject: [PATCH 09/20] accidentally dropped `MICROSECONDS_IN_SECOND` definition earlier --- ext/stackprof/stackprof.c | 1 + 1 file changed, 1 insertion(+) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 4f6ef2e5..b7156334 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -17,6 +17,7 @@ #include #define BUF_SIZE 2048 +#define MICROSECONDS_IN_SECOND 1000000 typedef struct { size_t total_samples; From 49a75ae927f7d3266bba85a02af91b9a573e7736 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 09:42:08 -0800 Subject: [PATCH 10/20] move `in_signal_handler` reset to `_stackprof.frames` reset block --- ext/stackprof/stackprof.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index b7156334..d76defb7 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -103,11 +103,13 @@ stackprof_start(int argc, VALUE *argv, VALUE self) if (!RTEST(mode)) mode = sym_wall; + // profiling can be paused and resumed, so allow for existing frames if (!_stackprof.frames) { _stackprof.frames = st_init_numtable(); _stackprof.overall_signals = 0; _stackprof.overall_samples = 0; _stackprof.during_gc = 0; + _stackprof.in_signal_handler = 0; } if (mode == sym_object) { @@ -140,7 +142,6 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.mode = mode; _stackprof.interval = interval; _stackprof.out = out; - _stackprof.in_signal_handler = 0; gettimeofday(&_stackprof.started_at, NULL); _stackprof.last_sample_at = _stackprof.started_at; From 197ef4ba3dd57c09198f70a3a5ebc7393c5ac275 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 09:47:21 -0800 Subject: [PATCH 11/20] test for `missed_samples` when sampling too fast --- test/test_stackprof.rb | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/test/test_stackprof.rb b/test/test_stackprof.rb index 0ae0712d..b6a941cc 100644 --- a/test/test_stackprof.rb +++ b/test/test_stackprof.rb @@ -196,13 +196,16 @@ def test_pathname_out end def test_wall_too_fast_no_hang - # The stack of `recurse` takes longer than 10μs to sample, + # The stack of `recurse` takes longer than 1μs to sample + # (probabilistically on a current CPU), # so if this was not handled properly, the job queue would pile up # faster than it was flushed, and the program would hang. # Timeout ensures that if this is broken, the test itself does not hang. - Timeout.timeout(10) do - StackProf.run(mode: :wall, interval: 10) { recurse } + results = Timeout.timeout(10) do + StackProf.run(mode: :wall, interval: 1) { recurse } end + # Program can use this to infer that sampling rate was too high + assert_operator results[:missed_samples], :>, 0 end def math From 566ce989fb6a0fd78ad6b31dad95426a22117e02 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 09:48:50 -0800 Subject: [PATCH 12/20] whitespace (tabs not spaces, ~consistently) --- ext/stackprof/stackprof.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index d76defb7..030a842b 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -109,7 +109,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.overall_signals = 0; _stackprof.overall_samples = 0; _stackprof.during_gc = 0; - _stackprof.in_signal_handler = 0; + _stackprof.in_signal_handler = 0; } if (mode == sym_object) { @@ -169,7 +169,7 @@ stackprof_stop(VALUE self) sa.sa_flags = SA_RESTART; sigemptyset(&sa.sa_mask); sigaction(_stackprof.mode == sym_wall ? SIGALRM : SIGPROF, &sa, NULL); - _stackprof.in_signal_handler = 0; + _stackprof.in_signal_handler = 0; } else if (_stackprof.mode == sym_custom) { /* sampled manually */ } else { From 02f59c16fcc158f5b8299192c6440a7498da52a6 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 10:46:34 -0800 Subject: [PATCH 13/20] don't reset `last_sample_at` when resuming --- ext/stackprof/stackprof.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 030a842b..44a2132f 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -86,6 +86,8 @@ stackprof_start(int argc, VALUE *argv, VALUE self) if (_stackprof.running) return Qfalse; + gettimeofday(&_stackprof.started_at, NULL); + rb_scan_args(argc, argv, "0:", &opts); if (RTEST(opts)) { @@ -110,6 +112,7 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.overall_samples = 0; _stackprof.during_gc = 0; _stackprof.in_signal_handler = 0; + _stackprof.last_sample_at = _stackprof.started_at; } if (mode == sym_object) { @@ -143,9 +146,6 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.interval = interval; _stackprof.out = out; - gettimeofday(&_stackprof.started_at, NULL); - _stackprof.last_sample_at = _stackprof.started_at; - return Qtrue; } From ac4905511ff3cbbcab55b97ad88ebfba8bf5c657 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 11:21:08 -0800 Subject: [PATCH 14/20] resolve compiler warnings with correct var types --- ext/stackprof/stackprof.c | 35 +++++++++++++++++++---------------- 1 file changed, 19 insertions(+), 16 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 44a2132f..bef895d8 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -45,7 +45,7 @@ static struct { struct timeval started_at; struct timeval last_sample_at; - int *raw_timestamp_deltas; + int64_t *raw_timestamp_deltas; size_t raw_timestamp_deltas_len; size_t raw_timestamp_deltas_capa; @@ -129,9 +129,14 @@ stackprof_start(int argc, VALUE *argv, VALUE self) sigaction(mode == sym_wall ? SIGALRM : SIGPROF, &sa, NULL); timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2LONG(interval); + timer.it_interval.tv_usec = NUM2INT(interval); timer.it_value = timer.it_interval; setitimer(mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); + + if (_stackprof.debug) { + printf("started with interval %d (%ld sec %d usec)\n", + NUM2INT(interval), timer.it_interval.tv_sec, timer.it_interval.tv_usec); + } } else if (mode == sym_custom) { /* sampled manually */ interval = Qnil; @@ -396,7 +401,7 @@ st_numtable_increment(st_table *table, st_data_t key, size_t increment) captured `timestamp_delta` microseconds after previous sample. */ void -stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) +stackprof_record_sample_for_stack(int frame_count, int64_t timestamp_delta) { int i, n; VALUE prev_frame = Qnil; @@ -514,10 +519,8 @@ stackprof_record_sample() if (_stackprof.debug) { int64_t time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); - printf("timestamp delta %ld usec since last, %ld since start, with interval %ld\n", - time_since_last_sample_usec, - time_since_start_usec, - NUM2LONG(_stackprof.interval)); + printf("timestamp delta %lld usec since last, %lld since start, with interval %d\n", + time_since_last_sample_usec, time_since_start_usec, NUM2INT(_stackprof.interval)); } frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); @@ -531,12 +534,11 @@ stackprof_record_sample() int64_t sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); printf("duration of stackprof_record_sample: %ld usec with interval %d\n", sampling_duration_usec, - NUM2LONG(_stackprof.interval)); + NUM2INT(_stackprof.interval)); - if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { + if (sampling_duration_usec >= NUM2INT(_stackprof.interval)) { fprintf(stderr, "INTERVAL IS TOO FAST: %d with interval %d\n", - sampling_duration_usec, - NUM2LONG(_stackprof.interval)); + sampling_duration_usec, NUM2INT(_stackprof.interval)); } } } @@ -544,7 +546,7 @@ stackprof_record_sample() void stackprof_record_gc_samples() { - int delta_to_first_unrecorded_gc_sample = 0; + int64_t delta_to_first_unrecorded_gc_sample = 0; int i; struct timeval t; struct timeval diff; @@ -554,7 +556,7 @@ stackprof_record_gc_samples() if (_stackprof.raw) { // We don't know when the GC samples were actually marked, so let's // assume that they were marked at a perfectly regular interval. - delta_to_first_unrecorded_gc_sample = timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); + delta_to_first_unrecorded_gc_sample = timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2INT(_stackprof.interval); if (delta_to_first_unrecorded_gc_sample < 0) { delta_to_first_unrecorded_gc_sample = 0; } @@ -564,7 +566,7 @@ stackprof_record_gc_samples() _stackprof.lines_buffer[0] = 0; for (i = 0; i < _stackprof.unrecorded_gc_samples; i++) { - int timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2LONG(_stackprof.interval); + int64_t timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2INT(_stackprof.interval); stackprof_record_sample_for_stack(1, timestamp_delta); } _stackprof.during_gc += _stackprof.unrecorded_gc_samples; @@ -619,7 +621,7 @@ static void stackprof_newobj_handler(VALUE tpval, void *data) { _stackprof.overall_signals++; - if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2LONG(_stackprof.interval)) + if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2INT(_stackprof.interval)) return; stackprof_job_handler(0); } @@ -671,8 +673,9 @@ stackprof_atfork_parent(void) struct itimerval timer; if (_stackprof.running) { if (_stackprof.mode == sym_wall || _stackprof.mode == sym_cpu) { + // TODO what if interval > 1 sec ?? timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2LONG(_stackprof.interval); + timer.it_interval.tv_usec = NUM2INT(_stackprof.interval); timer.it_value = timer.it_interval; setitimer(_stackprof.mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); } From e429dcc957a0141c23a6896a2eaa93e59a835240 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 11:40:44 -0800 Subject: [PATCH 15/20] Revert "resolve compiler warnings with correct var types" causes segfaults in tests :disappointed: This reverts commit ac4905511ff3cbbcab55b97ad88ebfba8bf5c657. --- ext/stackprof/stackprof.c | 35 ++++++++++++++++------------------- 1 file changed, 16 insertions(+), 19 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index bef895d8..44a2132f 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -45,7 +45,7 @@ static struct { struct timeval started_at; struct timeval last_sample_at; - int64_t *raw_timestamp_deltas; + int *raw_timestamp_deltas; size_t raw_timestamp_deltas_len; size_t raw_timestamp_deltas_capa; @@ -129,14 +129,9 @@ stackprof_start(int argc, VALUE *argv, VALUE self) sigaction(mode == sym_wall ? SIGALRM : SIGPROF, &sa, NULL); timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2INT(interval); + timer.it_interval.tv_usec = NUM2LONG(interval); timer.it_value = timer.it_interval; setitimer(mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); - - if (_stackprof.debug) { - printf("started with interval %d (%ld sec %d usec)\n", - NUM2INT(interval), timer.it_interval.tv_sec, timer.it_interval.tv_usec); - } } else if (mode == sym_custom) { /* sampled manually */ interval = Qnil; @@ -401,7 +396,7 @@ st_numtable_increment(st_table *table, st_data_t key, size_t increment) captured `timestamp_delta` microseconds after previous sample. */ void -stackprof_record_sample_for_stack(int frame_count, int64_t timestamp_delta) +stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) { int i, n; VALUE prev_frame = Qnil; @@ -519,8 +514,10 @@ stackprof_record_sample() if (_stackprof.debug) { int64_t time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); - printf("timestamp delta %lld usec since last, %lld since start, with interval %d\n", - time_since_last_sample_usec, time_since_start_usec, NUM2INT(_stackprof.interval)); + printf("timestamp delta %ld usec since last, %ld since start, with interval %ld\n", + time_since_last_sample_usec, + time_since_start_usec, + NUM2LONG(_stackprof.interval)); } frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); @@ -534,11 +531,12 @@ stackprof_record_sample() int64_t sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); printf("duration of stackprof_record_sample: %ld usec with interval %d\n", sampling_duration_usec, - NUM2INT(_stackprof.interval)); + NUM2LONG(_stackprof.interval)); - if (sampling_duration_usec >= NUM2INT(_stackprof.interval)) { + if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { fprintf(stderr, "INTERVAL IS TOO FAST: %d with interval %d\n", - sampling_duration_usec, NUM2INT(_stackprof.interval)); + sampling_duration_usec, + NUM2LONG(_stackprof.interval)); } } } @@ -546,7 +544,7 @@ stackprof_record_sample() void stackprof_record_gc_samples() { - int64_t delta_to_first_unrecorded_gc_sample = 0; + int delta_to_first_unrecorded_gc_sample = 0; int i; struct timeval t; struct timeval diff; @@ -556,7 +554,7 @@ stackprof_record_gc_samples() if (_stackprof.raw) { // We don't know when the GC samples were actually marked, so let's // assume that they were marked at a perfectly regular interval. - delta_to_first_unrecorded_gc_sample = timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2INT(_stackprof.interval); + delta_to_first_unrecorded_gc_sample = timeval_to_usec(&diff) - (_stackprof.unrecorded_gc_samples - 1) * NUM2LONG(_stackprof.interval); if (delta_to_first_unrecorded_gc_sample < 0) { delta_to_first_unrecorded_gc_sample = 0; } @@ -566,7 +564,7 @@ stackprof_record_gc_samples() _stackprof.lines_buffer[0] = 0; for (i = 0; i < _stackprof.unrecorded_gc_samples; i++) { - int64_t timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2INT(_stackprof.interval); + int timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2LONG(_stackprof.interval); stackprof_record_sample_for_stack(1, timestamp_delta); } _stackprof.during_gc += _stackprof.unrecorded_gc_samples; @@ -621,7 +619,7 @@ static void stackprof_newobj_handler(VALUE tpval, void *data) { _stackprof.overall_signals++; - if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2INT(_stackprof.interval)) + if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2LONG(_stackprof.interval)) return; stackprof_job_handler(0); } @@ -673,9 +671,8 @@ stackprof_atfork_parent(void) struct itimerval timer; if (_stackprof.running) { if (_stackprof.mode == sym_wall || _stackprof.mode == sym_cpu) { - // TODO what if interval > 1 sec ?? timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2INT(_stackprof.interval); + timer.it_interval.tv_usec = NUM2LONG(_stackprof.interval); timer.it_value = timer.it_interval; setitimer(_stackprof.mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); } From eb74750a49f255c8e1a6f05257dd82b8bec41796 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 11:49:39 -0800 Subject: [PATCH 16/20] (take 2) fix var types / compiler warnings - in `fprintf`s - `_stackprof.interval` is an int - `timestamp_delta` as `int64_t` - but doing the same with `_stackprof.raw_timestamp_deltas` makes it segfault! --- ext/stackprof/stackprof.c | 38 ++++++++++++++++++++------------------ 1 file changed, 20 insertions(+), 18 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 44a2132f..458c9d56 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -129,9 +129,14 @@ stackprof_start(int argc, VALUE *argv, VALUE self) sigaction(mode == sym_wall ? SIGALRM : SIGPROF, &sa, NULL); timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2LONG(interval); + timer.it_interval.tv_usec = NUM2INT(interval); timer.it_value = timer.it_interval; setitimer(mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); + + if (_stackprof.debug) { + printf("started with interval %d (%ld sec %d usec)\n", + NUM2INT(interval), timer.it_interval.tv_sec, timer.it_interval.tv_usec); + } } else if (mode == sym_custom) { /* sampled manually */ interval = Qnil; @@ -396,7 +401,7 @@ st_numtable_increment(st_table *table, st_data_t key, size_t increment) captured `timestamp_delta` microseconds after previous sample. */ void -stackprof_record_sample_for_stack(int frame_count, int timestamp_delta) +stackprof_record_sample_for_stack(int frame_count, int64_t timestamp_delta) { int i, n; VALUE prev_frame = Qnil; @@ -514,10 +519,8 @@ stackprof_record_sample() if (_stackprof.debug) { int64_t time_since_start_usec = diff_timevals_usec(&_stackprof.started_at, &sampling_start); - printf("timestamp delta %ld usec since last, %ld since start, with interval %ld\n", - time_since_last_sample_usec, - time_since_start_usec, - NUM2LONG(_stackprof.interval)); + printf("timestamp delta %lld usec since last, %lld since start, with interval %d\n", + time_since_last_sample_usec, time_since_start_usec, NUM2INT(_stackprof.interval)); } frame_count = rb_profile_frames(0, sizeof(_stackprof.frames_buffer) / sizeof(VALUE), _stackprof.frames_buffer, _stackprof.lines_buffer); @@ -529,14 +532,12 @@ stackprof_record_sample() if (_stackprof.debug) { int64_t sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); - printf("duration of stackprof_record_sample: %ld usec with interval %d\n", - sampling_duration_usec, - NUM2LONG(_stackprof.interval)); - - if (sampling_duration_usec >= NUM2LONG(_stackprof.interval)) { - fprintf(stderr, "INTERVAL IS TOO FAST: %d with interval %d\n", - sampling_duration_usec, - NUM2LONG(_stackprof.interval)); + printf("duration of stackprof_record_sample: %lld usec with interval %d\n", + sampling_duration_usec, NUM2INT(_stackprof.interval)); + + if (sampling_duration_usec >= NUM2INT(_stackprof.interval)) { + fprintf(stderr, "INTERVAL IS TOO FAST: %lld with interval %d\n", + sampling_duration_usec, NUM2INT(_stackprof.interval)); } } } @@ -544,7 +545,7 @@ stackprof_record_sample() void stackprof_record_gc_samples() { - int delta_to_first_unrecorded_gc_sample = 0; + int64_t delta_to_first_unrecorded_gc_sample = 0; int i; struct timeval t; struct timeval diff; @@ -564,7 +565,7 @@ stackprof_record_gc_samples() _stackprof.lines_buffer[0] = 0; for (i = 0; i < _stackprof.unrecorded_gc_samples; i++) { - int timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2LONG(_stackprof.interval); + int timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2INT(_stackprof.interval); stackprof_record_sample_for_stack(1, timestamp_delta); } _stackprof.during_gc += _stackprof.unrecorded_gc_samples; @@ -619,7 +620,7 @@ static void stackprof_newobj_handler(VALUE tpval, void *data) { _stackprof.overall_signals++; - if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2LONG(_stackprof.interval)) + if (RTEST(_stackprof.interval) && _stackprof.overall_signals % NUM2INT(_stackprof.interval)) return; stackprof_job_handler(0); } @@ -671,8 +672,9 @@ stackprof_atfork_parent(void) struct itimerval timer; if (_stackprof.running) { if (_stackprof.mode == sym_wall || _stackprof.mode == sym_cpu) { + // TODO what if interval > 1 sec ?? timer.it_interval.tv_sec = 0; - timer.it_interval.tv_usec = NUM2LONG(_stackprof.interval); + timer.it_interval.tv_usec = NUM2INT(_stackprof.interval); timer.it_value = timer.it_interval; setitimer(_stackprof.mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); } From 0d55084d2c5f64c961f8daf0c11f544f04adc74f Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 12:19:59 -0800 Subject: [PATCH 17/20] fix one more compiler warning with `int` vs `int64_t` --- ext/stackprof/stackprof.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 458c9d56..7c93e56c 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -546,7 +546,7 @@ void stackprof_record_gc_samples() { int64_t delta_to_first_unrecorded_gc_sample = 0; - int i; + unsigned long i; struct timeval t; struct timeval diff; gettimeofday(&t, NULL); @@ -565,7 +565,7 @@ stackprof_record_gc_samples() _stackprof.lines_buffer[0] = 0; for (i = 0; i < _stackprof.unrecorded_gc_samples; i++) { - int timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2INT(_stackprof.interval); + int64_t timestamp_delta = i == 0 ? delta_to_first_unrecorded_gc_sample : NUM2INT(_stackprof.interval); stackprof_record_sample_for_stack(1, timestamp_delta); } _stackprof.during_gc += _stackprof.unrecorded_gc_samples; From b6539f5f8ad308467271bd368198a0e911178d69 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 12:35:33 -0800 Subject: [PATCH 18/20] fix type, assignment, and allocation for `raw_timestamp_deltas` --- ext/stackprof/stackprof.c | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 7c93e56c..5c35c74e 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -45,7 +45,7 @@ static struct { struct timeval started_at; struct timeval last_sample_at; - int *raw_timestamp_deltas; + int64_t *raw_timestamp_deltas; size_t raw_timestamp_deltas_len; size_t raw_timestamp_deltas_capa; @@ -309,7 +309,7 @@ stackprof_results(int argc, VALUE *argv, VALUE self) raw_timestamp_deltas = rb_ary_new_capa(_stackprof.raw_timestamp_deltas_len); for (n = 0; n < _stackprof.raw_timestamp_deltas_len; n++) { - rb_ary_push(raw_timestamp_deltas, INT2FIX(_stackprof.raw_timestamp_deltas[n])); + rb_ary_push(raw_timestamp_deltas, LL2NUM(_stackprof.raw_timestamp_deltas[n])); } free(_stackprof.raw_timestamp_deltas); @@ -462,14 +462,14 @@ stackprof_record_sample_for_stack(int frame_count, int64_t timestamp_delta) /* If there's no timestamp delta buffer, allocate one */ if (!_stackprof.raw_timestamp_deltas) { _stackprof.raw_timestamp_deltas_capa = 100; - _stackprof.raw_timestamp_deltas = malloc(sizeof(int) * _stackprof.raw_timestamp_deltas_capa); + _stackprof.raw_timestamp_deltas = malloc(sizeof(int64_t) * _stackprof.raw_timestamp_deltas_capa); _stackprof.raw_timestamp_deltas_len = 0; } /* Double the buffer size if it's too small */ while (_stackprof.raw_timestamp_deltas_capa <= _stackprof.raw_timestamp_deltas_len + 1) { _stackprof.raw_timestamp_deltas_capa *= 2; - _stackprof.raw_timestamp_deltas = realloc(_stackprof.raw_timestamp_deltas, sizeof(int) * _stackprof.raw_timestamp_deltas_capa); + _stackprof.raw_timestamp_deltas = realloc(_stackprof.raw_timestamp_deltas, sizeof(int64_t) * _stackprof.raw_timestamp_deltas_capa); } /* Store the time delta (which is the amount of time between samples) */ From 2a311b899a4394329d8111dab817c251bc2b15a1 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 12:41:10 -0800 Subject: [PATCH 19/20] try to fix 'hanging' test in CI - MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit it appears that at 1μs, performance hit of profiling causes test to take >10s to run, and time out. try at 10μs instead. --- test/test_stackprof.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/test_stackprof.rb b/test/test_stackprof.rb index b6a941cc..60c0e769 100644 --- a/test/test_stackprof.rb +++ b/test/test_stackprof.rb @@ -196,13 +196,13 @@ def test_pathname_out end def test_wall_too_fast_no_hang - # The stack of `recurse` takes longer than 1μs to sample + # The stack of `recurse` takes longer than 10μs to sample # (probabilistically on a current CPU), # so if this was not handled properly, the job queue would pile up # faster than it was flushed, and the program would hang. # Timeout ensures that if this is broken, the test itself does not hang. results = Timeout.timeout(10) do - StackProf.run(mode: :wall, interval: 1) { recurse } + StackProf.run(mode: :wall, interval: 10) { recurse } end # Program can use this to infer that sampling rate was too high assert_operator results[:missed_samples], :>, 0 From 0f1394c981dd56bd9bed8aebc681db9eddbfce93 Mon Sep 17 00:00:00 2001 From: benbuckman Date: Mon, 11 Nov 2019 14:21:21 -0800 Subject: [PATCH 20/20] move debug-printf for interval, to include default --- ext/stackprof/stackprof.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index 5c35c74e..55f1b11d 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -132,11 +132,6 @@ stackprof_start(int argc, VALUE *argv, VALUE self) timer.it_interval.tv_usec = NUM2INT(interval); timer.it_value = timer.it_interval; setitimer(mode == sym_wall ? ITIMER_REAL : ITIMER_PROF, &timer, 0); - - if (_stackprof.debug) { - printf("started with interval %d (%ld sec %d usec)\n", - NUM2INT(interval), timer.it_interval.tv_sec, timer.it_interval.tv_usec); - } } else if (mode == sym_custom) { /* sampled manually */ interval = Qnil; @@ -151,6 +146,11 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.interval = interval; _stackprof.out = out; + if (_stackprof.debug) { + printf("started with interval %d (%ld sec %d usec)\n", + NUM2INT(_stackprof.interval), timer.it_interval.tv_sec, timer.it_interval.tv_usec); + } + return Qtrue; }