Refactor max idle filter by y-zeng · Pull Request #13594 · grpc/grpc

y-zeng · 2017-12-01T19:35:54Z

The previous implementation is faulty:
Assume we have one active call.

When it ends, decrease_call_count will be invoked, gpr_atm_full_fetch_add decreases call_count from 1 to 0.
At this time, a new call arrives, increase_call_count is called, gpr_atm_full_fetch_add sees that call_count is 0. It then cancels the timer.
decrease_call_count then continues its operation, and uses grpc_timer_init to set up the timer.

After these operations, there is still an active call, but the max_idle timer is set. At the time this remaining call ends, it will cause the crash reported in #12257.

The new implementation does not cancel max_idle_timer (unless the channel is shutting down). Instead, it uses idle_state to record if max_idle_timer is still valid. If the timer callback is called when the max_idle_timer is valid (i.e. idle_state is MAX_IDLE_STATE_TIMER_SET), the channel will be closed due to idleness, otherwise the channel won't be changed.

grpc-testing · 2017-12-01T19:39:08Z

****************************************************************

libgrpc.so

     VM SIZE                                                                              FILE SIZE
 ++++++++++++++ GROWING                                                                ++++++++++++++
  [ = ]       0 [None]                                                                 +1.37Ki  +0.0%
   +16%    +432 src/core/ext/filters/max_age/max_age_filter.cc                            +432   +16%
      [NEW]    +429 max_idle_timer_cb                                                         +429  [NEW]
      [NEW]    +139 increase_call_count(grpc_exec_ctx*, channel_data*) [clone .isra.0]        +139  [NEW]
      +160%    +131 decrease_call_count                                                       +131  +160%
      +4.1%     +32 init_channel_elem                                                          +32  +4.1%
       +50%      +3 destroy_call_elem                                                           +3   +50%

  +0.0%    +432 TOTAL                                                                  +1.79Ki  +0.0%


****************************************************************

libgrpc++.so

     VM SIZE        FILE SIZE
 ++++++++++++++  ++++++++++++++

  [ = ]       0        0  [ = ]

grpc-testing · 2017-12-01T19:50:48Z

[trickle] No significant performance differences

grpc-testing · 2017-12-01T20:31:03Z

Corrupt JSON data (indicates timeout or crash): 
    bm_fullstack_unary_ping_pong.BM_UnaryPingPong_MinInProcessCHTTP2_NoOpMutator_NoOpMutator__1_0.counters.old: 1


[microbenchmarks] Performance differences noted:
Benchmark                                                                                cpu_time    real_time
---------------------------------------------------------------------------------------  ----------  -----------
BM_StreamingPingPongWithCoalescingApi<MinInProcess, NoOpMutator, NoOpMutator>/32768/2/1  +5%         +5%

grpc-testing · 2017-12-02T01:28:46Z

****************************************************************

libgrpc.so

     VM SIZE                                                                              FILE SIZE
 ++++++++++++++ GROWING                                                                ++++++++++++++
  +0.0%     +16 [None]                                                                 +1.17Ki  +0.0%
   +15%    +400 src/core/ext/filters/max_age/max_age_filter.cc                            +400   +15%
      [NEW]    +397 max_idle_timer_cb                                                         +397  [NEW]
      [NEW]    +139 increase_call_count(grpc_exec_ctx*, channel_data*) [clone .isra.0]        +139  [NEW]
      +160%    +131 decrease_call_count                                                       +131  +160%
      +4.1%     +32 init_channel_elem                                                          +32  +4.1%
       +50%      +3 destroy_call_elem                                                           +3   +50%

  +0.0%    +416 TOTAL                                                                  +1.56Ki  +0.0%


****************************************************************

libgrpc++.so

     VM SIZE        FILE SIZE
 ++++++++++++++  ++++++++++++++

  [ = ]       0        0  [ = ]

grpc-testing · 2017-12-02T01:41:09Z

[trickle] No significant performance differences

grpc-testing · 2017-12-02T02:21:02Z

[microbenchmarks] No significant performance differences

grpc-testing · 2017-12-04T23:27:04Z

****************************************************************

libgrpc.so

     VM SIZE                                                                              FILE SIZE
 ++++++++++++++ GROWING                                                                ++++++++++++++
  +0.0%     +16 [None]                                                                 +1.20Ki  +0.0%
   +15%    +400 src/core/ext/filters/max_age/max_age_filter.cc                            +400   +15%
      [NEW]    +397 max_idle_timer_cb                                                         +397  [NEW]
      [NEW]    +139 increase_call_count(grpc_exec_ctx*, channel_data*) [clone .isra.0]        +139  [NEW]
      +160%    +131 decrease_call_count                                                       +131  +160%
      +4.1%     +32 init_channel_elem                                                          +32  +4.1%
       +50%      +3 destroy_call_elem                                                           +3   +50%

  +0.0%    +416 TOTAL                                                                  +1.59Ki  +0.0%


****************************************************************

libgrpc++.so

     VM SIZE        FILE SIZE
 ++++++++++++++  ++++++++++++++

  [ = ]       0        0  [ = ]

grpc-testing · 2017-12-04T23:40:18Z

[trickle] No significant performance differences

grpc-testing · 2017-12-05T00:18:38Z

[microbenchmarks] No significant performance differences

y-zeng · 2017-12-11T18:46:50Z

Ping 😅

y-zeng · 2018-01-22T20:26:34Z

cc @mehrdada

grpc-testing · 2018-01-22T20:53:29Z

****************************************************************

libgrpc.so

     VM SIZE                                                      FILE SIZE
 ++++++++++++++ GROWING                                        ++++++++++++++
   +17%    +448 src/core/ext/filters/max_age/max_age_filter.cc    +448   +17%
      [NEW]    +394 max_idle_timer_cb                                 +394  [NEW]
      +195%    +160 decrease_call_count                               +160  +195%
      +286%    +103 increase_call_count                               +103  +286%
      +2.1%     +16 init_channel_elem                                  +16  +2.1%

 -+-+-+-+-+-+-+ MIXED                                          +-+-+-+-+-+-+-
  -0.0%      -8 [None]                                         +1.26Ki  +0.0%

  +0.0%    +440 TOTAL                                          +1.70Ki  +0.0%


****************************************************************

libgrpc++.so

     VM SIZE        FILE SIZE
 ++++++++++++++  ++++++++++++++

  [ = ]       0        0  [ = ]

grpc-testing · 2018-01-22T21:03:08Z

[trickle] No significant performance differences

grpc-testing · 2018-01-22T21:46:04Z

[microbenchmarks] No significant performance differences

sreecha · 2018-01-22T23:08:53Z

src/core/ext/filters/max_age/max_age_filter.cc

-        &chand->max_idle_timer,
-        grpc_core::ExecCtx::Get()->Now() + chand->max_connection_idle,
-        &chand->close_max_idle_channel);
+    gpr_atm_no_barrier_store(&chand->last_enter_idle_time_millis,


Shouldn't this be set when you actually change the idle_state to MAX_IDLE_STATE_TIMER_SET ?

Thanks a lot for the review!

The MAX_IDLE_STATE_TIMER_SET branch is using grpc_core::ExecCtx::Get()->Now() inside grpc_timer_init() as last_enter_idle_time_millis. This stored last_enter_idle_time_millis is prepared for the MAX_IDLE_STATE_SEEN_EXIT_IDLE branch.

By setting it beforehand and using the release semantic, we can make sure if a thread sees MAX_IDLE_STATE_SEEN_ENTER_IDLE, it must see the correct last_enter_idle_time_millis.

sreecha · 2018-01-22T23:09:25Z

src/core/ext/filters/max_age/max_age_filter.cc

-    GRPC_LOG_IF_ERROR("close_max_idle_channel", error);
+    while (true) {
+      gpr_atm idle_state = gpr_atm_acq_load(&chand->idle_state);
+      if (idle_state == MAX_IDLE_STATE_TIMER_SET) {


Might help to rewrite this as a case statement to be consistent with the other two places..

I'll make the change in #14122

sreecha · 2018-01-22T23:10:37Z

src/core/ext/filters/max_age/max_age_filter.cc

  grpc_connectivity_state connectivity_state;
  /* Number of active calls */
  gpr_atm call_count;
+  /* 'idle_state' holds the states of max_idle_timer and channel idleness.


Thanks for the detailed comment here. If you don't mind, it would help if you write a brief description of what each state means..
especially the MAX_IDLE_STATE_SEEN_EXIT_IDLE and MAX_IDLE_STATE_SEEN_ENTER_IDLE .

I'll add the description in #14122

Backport #13594 to v1.9.x

mehrdada · 2018-01-31T07:02:25Z

Anything blocking this from being merged? I'm asking since the backport already on 1.9.x and will come to master on the next upmerge and will cause a conflict if there are additional changes on this one, so clicking the merge button before the upmerge might be a good idea?

abaldeva · 2018-02-06T00:11:33Z

y-zeng,

I tested the fix with grpc 1.9.0 upgrade. Unfortunately, enabling the option now causes a massive memory leak instead of crashing which is also bad. I am bombarding my server with an rpc and here is a log on Windows (I am able to reproduce the leak on Linux as well).

Would you like a new issue created for it or should this really be addressed as part of this issue?
memory_leak.txt

Thanks.

y-zeng · 2018-02-06T00:23:50Z

@mehrdada There are a few differences between this PR and the one merged in 1.9.x. Maybe we can just keep the changes in the up-merge and close this one?

y-zeng · 2018-02-06T00:25:32Z

@abaldeva Thanks for reporting the memory leak issue! I'll try reproducing it on 1.9.0 and see if we need to create a new issue to track it.

abaldeva · 2018-02-13T17:28:57Z

@y-zeng , did the log file I added help you in seeing the source of the leak?

Thanks.

mehrdada · 2018-02-13T18:10:28Z

@y-zeng totally missed your comment here. I have upmerged changes to master last week or so. Please take a quick look at current master and feel free to close this if it is satisfactory.

abaldeva · 2018-02-16T18:18:08Z

Created a new issue for the memory leak here - #14447

y-zeng added 3 commits November 30, 2017 22:24

Refactor max_idle

08d2dc5

Add necessary retries for atomic state changes

34807df

Try again when idle_state is unexpected

7b67b5d

y-zeng added the disposition/Work In Progress label Dec 1, 2017

Fix asan issues

7472fbb

Document idle_state transistions

34b2823

y-zeng assigned sreecha Dec 4, 2017

y-zeng requested a review from sreecha December 4, 2017 23:23

y-zeng removed the disposition/Work In Progress label Dec 4, 2017

y-zeng added the priority/P0/RELEASE BLOCKER label Jan 22, 2018

Merge remote-tracking branch 'upstream/master' into max_age_fix

0249610

y-zeng removed the priority/P0/RELEASE BLOCKER label Jan 22, 2018

sreecha reviewed Jan 22, 2018

View reviewed changes

y-zeng mentioned this pull request Jan 23, 2018

Backport #13594 to v1.9.x #14122

Merged

sreecha approved these changes Jan 23, 2018

View reviewed changes

y-zeng added a commit that referenced this pull request Jan 24, 2018

Merge pull request #14122 from y-zeng/max_age_19x

02384e3

Backport #13594 to v1.9.x

mehrdada closed this Feb 16, 2018

abaldeva mentioned this pull request May 16, 2018

timer thread crash #12257

Closed

lock bot locked as resolved and limited conversation to collaborators Jan 20, 2019

lock bot unassigned sreecha Jan 20, 2019

Conversation

y-zeng commented Dec 1, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

grpc-testing commented Dec 1, 2017

Uh oh!

grpc-testing commented Dec 1, 2017

Uh oh!

grpc-testing commented Dec 1, 2017

Uh oh!

grpc-testing commented Dec 2, 2017

Uh oh!

grpc-testing commented Dec 2, 2017

Uh oh!

grpc-testing commented Dec 2, 2017

Uh oh!

grpc-testing commented Dec 4, 2017

Uh oh!

grpc-testing commented Dec 4, 2017

Uh oh!

grpc-testing commented Dec 5, 2017

Uh oh!

y-zeng commented Dec 11, 2017

Uh oh!

y-zeng commented Jan 22, 2018

Uh oh!

grpc-testing commented Jan 22, 2018

Uh oh!

grpc-testing commented Jan 22, 2018

Uh oh!

grpc-testing commented Jan 22, 2018

Uh oh!

sreecha Jan 22, 2018

Choose a reason for hiding this comment

Uh oh!

y-zeng Jan 23, 2018

Choose a reason for hiding this comment

Uh oh!

sreecha Jan 22, 2018

Choose a reason for hiding this comment

Uh oh!

y-zeng Jan 23, 2018

Choose a reason for hiding this comment

Uh oh!

sreecha Jan 22, 2018

Choose a reason for hiding this comment

Uh oh!

y-zeng Jan 23, 2018

Choose a reason for hiding this comment

Uh oh!

mehrdada commented Jan 31, 2018

Uh oh!

abaldeva commented Feb 6, 2018

Uh oh!

y-zeng commented Feb 6, 2018

Uh oh!

y-zeng commented Feb 6, 2018

Uh oh!

abaldeva commented Feb 13, 2018

Uh oh!

mehrdada commented Feb 13, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

abaldeva commented Feb 16, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

y-zeng commented Dec 1, 2017 •

edited

Loading

mehrdada commented Feb 13, 2018 •

edited

Loading