New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

class_serial increment at each request #25068

Closed
etiennebarrie opened this Issue May 18, 2016 · 2 comments

Comments

Projects
None yet
4 participants
@etiennebarrie
Contributor

etiennebarrie commented May 18, 2016

Steps to reproduce

Clone https://github.com/etiennebarrie/class_serial or:

$ rails _5.0.0.rc1_ new class_serial
$ cd class_serial/
$ rails generate controller ruby_vm stat
diff --git a/app/controllers/ruby_vm_controller.rb b/app/controllers/ruby_vm_controller.rb
index 422b18b..6b438d0 100644
--- a/app/controllers/ruby_vm_controller.rb
+++ b/app/controllers/ruby_vm_controller.rb
@@ -1,4 +1,5 @@
 class RubyVmController < ApplicationController
   def stat
+    render json: RubyVM.stat
   end
 end

Then run the server, access http://localhost:3000/ruby_vm/stat and see class_serial being incremented at each request, e.g.:

$ curl --silent localhost:3000/ruby_vm/stat | jq .class_serial
150790
$ curl --silent localhost:3000/ruby_vm/stat | jq .class_serial
150791
$ curl --silent localhost:3000/ruby_vm/stat | jq .class_serial
150792

In development, you have to warm the cache with one request first. Between the first and second requests, class_serial increments by more than 1, but then it also increments by one for each request.

Expected behavior

class_serial should not change between requests

Actual behavior

class_serial is incremented at each request

System configuration

Rails version:
5.0.0.rc1

Ruby version:
2.3.1

Debugging

It was fine until beta3, and you start seeing this behaviour starting with beta4. I think 291a098 is what caused it to happen.

Using @tenderlove's patch to add the class_serial_incr event to TracePoint (https://github.com/tenderlove/ruby/tree/IC_trace), I was able to pinpoint the class serial increment to using instance_exec in ActiveSupport::Callbacks::Callback#make_lambda, and using some puts debugging I found that it came from defining callbacks with a block.

There are three blocks that are called in this case:

Removing the first call to instance_exec by passing self and defining the before method was not enough to remove the issue:

diff --git a/activerecord/lib/active_record/query_cache.rb b/activerecord/lib/active_record/query_cache.rb
index ca12a60..e6feb97 100644
--- a/activerecord/lib/active_record/query_cache.rb
+++ b/activerecord/lib/active_record/query_cache.rb
@@ -43,10 +43,12 @@ def self.complete(state)
     def self.install_executor_hooks(executor = ActiveSupport::Executor)
       executor.register_hook(self)

-      executor.to_complete do
-        unless ActiveRecord::Base.connection.transaction_open?
-          ActiveRecord::Base.clear_active_connections!
-        end
+      executor.to_complete(self)
+    end
+
+    def self.before(_executor)
+      unless ActiveRecord::Base.connection.transaction_open?
+        ActiveRecord::Base.clear_active_connections!
       end
     end
   end

By displaying something inside the TracePoint, having a byebug inside the lambda at ActiveSupport::Callbacks::Callback#make_lambda, I think I'm pretty sure now only the to_run is causing the class serial increment.

cc @matthewd

Edit: forgot I also built an example app: https://github.com/etiennebarrie/class_serial

@rthbound

This comment has been minimized.

Contributor

rthbound commented Sep 9, 2016

@rafaelfranca & @etiennebarrie:

I'm not crystal clear on what the incorrect behavior looks like. I've created some reproduction steps using rails' bug report templates (in guides/bug_report_templates/*).

Reproduction script is here: https://gist.github.com/rthbound/4a904c925bcc140ba9c669de5b54c407

Current output:

W, [2016-09-09T16:14:24.838610 #15760] WARN -- : 140704 blew up to [140704, 140715, 140715, 140715, 140715]
F

Finished in 0.300134s, 3.3318 runs/s, 3.3318 assertions/s.

  1. Failure:
    BugTest#test_returns_success [action_controller_master.rb:59]:
    Expected: 1
    Actual: 2

So, at this time I'm not observing class_serial incrementing on every request, but it does jump by several after the first request.

Hope this helps.

@etiennebarrie

This comment has been minimized.

Contributor

etiennebarrie commented Oct 4, 2016

I can confirm it works great. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment