diff --git a/ext/stackprof/stackprof.c b/ext/stackprof/stackprof.c index ae3467d4..55f1b11d 100644 --- a/ext/stackprof/stackprof.c +++ b/ext/stackprof/stackprof.c @@ -14,8 +14,10 @@ #include #include #include +#include #define BUF_SIZE 2048 +#define MICROSECONDS_IN_SECOND 1000000 typedef struct { size_t total_samples; @@ -29,18 +31,21 @@ static struct { int running; int raw; int aggregate; + int in_signal_handler; VALUE mode; VALUE interval; VALUE out; + VALUE debug; VALUE *raw_samples; size_t raw_samples_len; size_t raw_samples_capa; size_t raw_sample_index; + 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; @@ -60,43 +65,54 @@ 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_debug; static VALUE sym_gc_samples, objtracer; static VALUE gc_hook; static VALUE rb_mStackProf; static void stackprof_newobj_handler(VALUE, void*); static void stackprof_signal_handler(int sig, siginfo_t* sinfo, void* ucontext); +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) { struct sigaction sa; struct itimerval timer; - VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse; + VALUE opts = Qnil, mode = Qnil, interval = Qnil, out = Qfalse, debug = Qfalse; int raw = 0, aggregate = 1; if (_stackprof.running) return Qfalse; + gettimeofday(&_stackprof.started_at, NULL); + rb_scan_args(argc, argv, "0:", &opts); if (RTEST(opts)) { mode = rb_hash_aref(opts, sym_mode); interval = rb_hash_aref(opts, sym_interval); out = rb_hash_aref(opts, sym_out); + 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; + // 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; + _stackprof.last_sample_at = _stackprof.started_at; } if (mode == sym_object) { @@ -113,7 +129,7 @@ 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); } else if (mode == sym_custom) { @@ -130,8 +146,9 @@ stackprof_start(int argc, VALUE *argv, VALUE self) _stackprof.interval = interval; _stackprof.out = out; - if (raw) { - gettimeofday(&_stackprof.last_sample_at, NULL); + 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; @@ -157,6 +174,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 { @@ -291,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); @@ -377,8 +395,13 @@ 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 num, int timestamp_delta) +stackprof_record_sample_for_stack(int frame_count, int64_t timestamp_delta) { int i, n; VALUE prev_frame = Qnil; @@ -389,29 +412,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; @@ -428,8 +451,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; } @@ -439,21 +462,21 @@ stackprof_record_sample_for_stack(int num, int 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) */ _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); @@ -482,41 +505,57 @@ stackprof_record_sample_for_stack(int num, int timestamp_delta) prev_frame = frame; } - if (_stackprof.raw) { - gettimeofday(&_stackprof.last_sample_at, NULL); - } + gettimeofday(&_stackprof.last_sample_at, NULL); } void stackprof_record_sample() { - int timestamp_delta = 0; - int num; - if (_stackprof.raw) { - struct timeval t; - struct timeval diff; - gettimeofday(&t, NULL); - timersub(&t, &_stackprof.last_sample_at, &diff); - timestamp_delta = (1000 * diff.tv_sec) + diff.tv_usec; + int frame_count; + struct timeval sampling_start, sampling_finish; + + gettimeofday(&sampling_start, NULL); + int64_t time_since_last_sample_usec = diff_timevals_usec(&_stackprof.last_sample_at, &sampling_start); + + 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)); + } + + 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; + + if (_stackprof.debug) { + int64_t sampling_duration_usec = diff_timevals_usec(&sampling_start, &sampling_finish); + 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)); + } } - 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); } void 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); + int64_t delta_to_first_unrecorded_gc_sample = 0; + unsigned long i; + 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 = (1000 * diff.tv_sec + diff.tv_usec) - (_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; } @@ -526,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); + 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; @@ -536,31 +575,39 @@ 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++; + + // 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) { + if (_stackprof.debug) + 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); @@ -573,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); } @@ -625,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); } @@ -639,6 +687,22 @@ stackprof_atfork_child(void) stackprof_stop(rb_mStackProf); } +int64_t timeval_to_usec(struct timeval *diff) { + return MICROSECONDS_IN_SECOND * diff->tv_sec + diff->tv_usec; +} + +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; + 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) { @@ -664,6 +728,7 @@ Init_stackprof(void) S(out); S(frames); S(aggregate); + S(debug); #undef S gc_hook = Data_Wrap_Struct(rb_cObject, stackprof_gc_mark, NULL, &_stackprof); diff --git a/test/test_stackprof.rb b/test/test_stackprof.rb index 27da5c37..60c0e769 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,19 @@ 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 + # (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: 10) { recurse } + end + # Program can use this to infer that sampling rate was too high + assert_operator results[:missed_samples], :>, 0 + end + def math 250_000.times do 2 ** 10 @@ -207,4 +221,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