Prevent hanging when sample collection time > interval by benbuckman · Pull Request #124 · tmm1/stackprof

benbuckman · 2019-11-07T08:23:24Z

This attempts to fix the bug described in #123, in which, when interval is faster than the time required to record and analyze stack frames, the job queue piles up faster than it's flushed and the program hangs.

Pieces:

Moves the in_signal_handler lock to the global _stackprof struct, and adds a check, and escape hatch, in stackprof_signal_handler.
Adds a test which demonstrates the hanging behavior and the fix for it.
Adds helpers timeval_to_usec and diff_timevals_usec for working with time durations more easily as long ints of microseconds, rather than timeval structs.
Adds a debug mode with stdout+stderr output recording the internal timings and flow.
Adds some comments and renames some variables for clarity.

More context on the underlying bug, and consideration of alternative approaches, is at #123.

Motivation:
We would like to use StackProf on a large-scale Ruby application in production. The inability to set an interval that is both fast enough to produce useful data, and guaranteed to never hang the program, is a blocker to doing so.

Caveats:

I am an amateur with C. It took a lot of trial and error with this code and https://repl.it/languages/c to get this working.
I have not yet analyzed what the escape hatch in stackprof_signal_handler does to the quality of the final results. (At the end of the day, it's a kind of user or program error if the interval is so fast that the escape hatch is necessary. The question is how to deal with it.)
I have mostly tested this with wall mode; I have not yet analyzed how this bug or fix work with cpu or object modes (though I suspect they're similar).

cc @NickLaMuro, thank you for your engagement with #123!

…dler

benbuckman · 2019-11-07T08:24:31Z

ext/stackprof/stackprof.c

+    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.
+*/


(This is based on my understanding of the code, please correct if I'm misunderstanding. I'm also not sure what the canonical comment format should be here.)

benbuckman · 2019-11-07T08:26:32Z

ext/stackprof/stackprof.c

-    if (_stackprof.raw) {
-	gettimeofday(&_stackprof.last_sample_at, NULL);
-    }
+    gettimeofday(&_stackprof.last_sample_at, NULL);


(It seems simpler, and trivial, to assign this always, rather than track the downstream paths that do or don't need it.)

benbuckman · 2019-11-07T08:30:02Z

ext/stackprof/stackprof.c

+    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);


(Note, this replaces the timestamp math fix in #122.)

Instead of long int, include stdint.h and use int64_t

benbuckman · 2019-11-07T08:37:35Z

ext/stackprof/stackprof.c

+    return MICROSECONDS_IN_SECOND * diff->tv_sec + diff->tv_usec;
+}
+
+long int diff_timevals_usec(struct timeval *start, struct timeval *end) {


(I adapted this from an algorithm at https://www.guyrutenberg.com/2007/09/22/profiling-code-using-clock_gettime/, and tested it with this repl: https://repl.it/@BenBuckman/SanityCheck-Timevals)

ext/stackprof/stackprof.c

benbuckman · 2019-11-08T21:27:08Z

@tmm1 Thanks for your feedback so far.
What do you think of this overall?
How would you like StackProf to handle the scenario described here – should it skip the signal handler (as currently implemented), or fill in fake frames, or stop profiling and raise a (e.g.) IntervalTooFast error later on StackProf.results (or at the end of run)?

benbuckman · 2019-11-08T23:32:13Z

Thinking about it some more, another option would be to track and expose _stackprof.skipped_frames, and let the program use it after collecting the data, if it cares to.

benbuckman · 2019-11-11T17:13:22Z

_stackprof.skipped_frames

I see an integer missed_samples in the results,
defined at

stackprof/ext/stackprof/stackprof.c

Line 655 in 1d5ae02

S(missed_samples);

~~but it's never set in the C code, so it's always 0.~~
~~Was the original intention for missed_samples the same as I'm proposing here?~~
never mind, the search results missed where it's used,

stackprof/ext/stackprof/stackprof.c

Line 260 in 1d5ae02

    
           rb_hash_aset(results, sym_missed_samples, SIZET2NUM(_stackprof.overall_signals - _stackprof.overall_samples));

It looks like missed_samples, as already implemented, would correctly count the number of signals skipped by the new escape hatch. Excellent.

benbuckman · 2019-11-11T17:54:14Z

@tmm1 || @tenderlove || other maintainers, do you have time to review this?
Thank you!

causes segfaults in tests 😞 This reverts commit ac49055.

- 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!

benbuckman · 2019-11-11T20:07:00Z

@tmm1 I'm using int64_t now as suggested, but it's inconsistent – _stackprof.raw_timestamp_deltas still holds ints – and attempting to change that ... causes segfaults in tests (https://travis-ci.org/tmm1/stackprof/builds/610510787).

Edit: this is fixed, I needed to also change the malloc size

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.

benbuckman · 2019-11-11T22:11:06Z

ext/stackprof/stackprof.c

+
+        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);


(This highlights the separate issue of #125)

benbuckman · 2019-11-11T22:22:50Z

ext/stackprof/stackprof.c

-    if (raw) {
-	gettimeofday(&_stackprof.last_sample_at, NULL);
+    if (_stackprof.debug) {
+        printf("started with interval %d (%ld sec %d usec)\n",


(This highlights the separate issue of #125)

benbuckman added 7 commits November 7, 2019 00:00

WIP

39d345b

num -> frame_count

e8f7e50

comment on stackprof_record_sample_for_stack

ce003df

WIP always capture timeofday, last_sample_at

bbdbcbb

WIP - measuring correctly in stackprof_record_sample

1d4da7b

move in_signal_handler lock to global struct, checked in signal han…

5bb43e3

…dler

debug mode

9ce3a2f

benbuckman commented Nov 7, 2019

View reviewed changes

benbuckman mentioned this pull request Nov 7, 2019

Fix timestamp math: 1 million microseconds per second #122

Closed

benbuckman commented Nov 7, 2019

View reviewed changes

benbuckman mentioned this pull request Nov 7, 2019

Program hangs if sample-collection time is > interval #123

Open

3 tasks

benbuckman commented Nov 7, 2019

View reviewed changes

ext/stackprof/stackprof.c Show resolved Hide resolved

benbuckman added 2 commits November 8, 2019 13:21

use int64_t instead of long int

2d3e274

accidentally dropped MICROSECONDS_IN_SECOND definition earlier

d250bd4

benbuckman added 2 commits November 11, 2019 09:42

move in_signal_handler reset to _stackprof.frames reset block

49a75ae

test for missed_samples when sampling too fast

197ef4b

benbuckman changed the title ~~[WIP] Prevent hanging when sample collection time > interval~~ Prevent hanging when sample collection time > interval Nov 11, 2019

whitespace (tabs not spaces, ~consistently)

566ce98

benbuckman requested a review from tmm1 November 11, 2019 17:52

benbuckman added 4 commits November 11, 2019 10:46

don't reset last_sample_at when resuming

02f59c1

resolve compiler warnings with correct var types

ac49055

Revert "resolve compiler warnings with correct var types"

e429dcc

causes segfaults in tests 😞 This reverts commit ac49055.

(take 2) fix var types / compiler warnings

eb74750

- 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!

benbuckman added 3 commits November 11, 2019 12:25

fix one more compiler warning with int vs int64_t

0d55084

fix type, assignment, and allocation for raw_timestamp_deltas

b6539f5

try to fix 'hanging' test in CI -

2a311b8

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.

benbuckman commented Nov 11, 2019

View reviewed changes

move debug-printf for interval, to include default

0f1394c

benbuckman commented Nov 11, 2019

View reviewed changes

jhawthorn mentioned this pull request Apr 28, 2021

Collect stack frames immediately in Ruby 3.0 #150

Merged

Conversation

benbuckman commented Nov 7, 2019

Uh oh!

benbuckman Nov 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

benbuckman Nov 7, 2019

Choose a reason for hiding this comment

Uh oh!

benbuckman Nov 7, 2019

Choose a reason for hiding this comment

Uh oh!

tmm1 Nov 7, 2019

Choose a reason for hiding this comment

Uh oh!

benbuckman Nov 8, 2019

Choose a reason for hiding this comment

Uh oh!

benbuckman Nov 7, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

benbuckman commented Nov 8, 2019

Uh oh!

benbuckman commented Nov 8, 2019

Uh oh!

benbuckman commented Nov 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

benbuckman commented Nov 11, 2019

Uh oh!

benbuckman commented Nov 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

benbuckman Nov 11, 2019

Choose a reason for hiding this comment

Uh oh!

benbuckman Nov 11, 2019

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

benbuckman Nov 7, 2019 •

edited

Loading

benbuckman commented Nov 11, 2019 •

edited

Loading

benbuckman commented Nov 11, 2019 •

edited

Loading