rails activesupport 通知 - 错误的数据库运行时值

Posted 2023-02-15

技术标签:

【中文标题】rails activesupport 通知 - 错误的数据库运行时值【英文标题】：rails activesupport notifications - wrong db runtime value 【发布时间】：2013-01-17 20:53:09 【问题描述】：

我正在尝试记录我的 REST API 应用程序的请求。我正在为此使用 rails 通知，比如这里http://railscasts.com/episodes/249-notifications-in-rails-3

我不明白如何解决 Rails 通知的一个问题。

我的初始化代码

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, start, finish, id, payload|
 p name
 p start 
 p finish
 p id
 p payload
end



Controller respond section

    class PostsController < ApplicationController
      # GET /posts
      # GET /posts.json

      respond_to  :json, :html
     ....
end

控制器创建动作

  def create
    @post = Post.new(params[:post])
    @post.save!
    respond_with(@post, :location => nil)
 end

控制台输出

"process_action.action_controller"
2013-02-02 20:13:11 +0200
2013-02-02 20:13:11 +0200
"951b8999e9b71d4a8949"
:controller=>"PostsController", :action=>"create", :params=>"utf8"=>"✓", "authenticity_token"=>"1WugY9gh6ZCRXjfBTuckye3c9XDvtCqMQ2JdBpCo88s=", "post"=>"name"=>"post3", "title"=>"post3", "content"=>"post3", "commit"=>"Create Post", "action"=>"create", "controller"=>"posts", :format=>:html, :method=>"POST", :path=>"/posts", :status=>302, :view_runtime=>nil, :db_runtime=>0

如你所见:db_runtime=>0

但是，如果我将控制器操作代码更改为默认脚手架

  def create
    @post = Post.new(params[:post])
    #@post.save!
    #respond_with(@post)
    respond_to do |format|
      if @post.save
        format.html  redirect_to @post, notice: 'Post was successfully created.' 
        format.json  render json: @post, status: :created, location: @post 
      else
        format.html  render action: "new" 
        format.json  render json: @post.errors, status: :unprocessable_entity 
      end
    end
  end

我可以看到

"process_action.action_controller"
2013-02-02 20:22:51 +0200
2013-02-02 20:22:51 +0200
"bf2a3173c08a0fd9008e"
:controller=>"PostsController", :action=>"create", :params=>"utf8"=>"✓", "authenticity_token"=>"1WugY9gh6ZCRXjfBTuckye3c9XDvtCqMQ2JdBpCo88s=", "post"=>"name"=>"post3", "title"=>"post3", "content"=>"post3", "commit"=>"Create Post", "action"=>"create", "controller"=>"posts", :format=>:html, :method=>"POST", :path=>"/posts", :status=>302, :view_runtime=>nil, :db_runtime=>4.727

:db_runtime=>4.727

这是什么原因以及如何修复它以使其在第一个示例中正常工作？谢谢！

更新

 bundle show rails
/Users/admin/.rvm/gems/ruby-1.9.3-p125/gems/rails-3.2.11
rvm current
ruby-1.9.3-p125

UPD2

当我使用respond_with时，它似乎不起作用！有人能告诉我为什么吗？谢谢

【问题讨论】：

嗨 Fivell，刚才我试图生成同样的东西。这是我使用respond_with得到的：通知：process_action.action_controller 2013-02-06 13:59:21 +0600 2013-02-06 13:59:21 +0600 f2da3803410cccda546a :controller=>"PostsController", : action=>"show", :params=>"action"=>"show", "controller"=>"posts", "id"=>"12", :format=>:html, :method= >"GET", :path=>"/posts/12", :status=>200, :view_runtime=>9.479712, :db_runtime=>0.267212 rails 3.2.11，ruby 1.9.3p194（2012-04-20 修订版 35410）[x86_64-linux] 嗨，说它适用于 GET，但不适用于 POST 啊啊啊，原来如此，得到0，真是奇怪。 @SaidKaldybaev，我认为这是 Rails 中的错误！ 【参考方案1】：

好的，这似乎是一个错误。让我们看看发生了什么：

首先，我们有用于控制器操作的 AR railtie 及其实现，用于使用 cleanup_view_runtime 钩子设置 db_runtime

def cleanup_view_runtime
      if ActiveRecord::Base.connected?
       db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime
       runtime = super
       db_rt_after_render = ActiveRecord::LogSubscriber.reset_runtime
       self.db_runtime = db_rt_before_render + db_rt_after_render
       runtime - db_rt_after_render
     else
       super
     end
end

App 调用控制器动作 -> 动作执行一些数据库查询并渲染一些东西 -> 在渲染前后 AR Logger 保存运行时数据。很好。

让我们看看 respond_with 是如何工作的

def respond_with(*resources, &block)
  raise "In order to use respond_with, first you need to declare the formats your " <<
        "controller responds to in the class level" if self.class.mimes_for_respond_to.empty?

  if collector = retrieve_collector_from_mimes(&block)
    options = resources.size == 1 ?  : resources.extract_options!
    options[:default_response] = collector.response
    (options.delete(:responder) || self.class.responder).call(self, resources, options)
  end
end

def self.call(*args)
  new(*args).respond
end

def to_format
  if get? || !has_errors? || response_overridden?
    default_render
  else
    display_errors
  end
rescue ActionView::MissingTemplate => e
  api_behavior(e)
end

这里的代码似乎太多了，但你应该看到这个问题的调用堆栈：respond_with -> self.class.responder.respond -> self.class.responder.to_format -> default_render -> default_renderer raise ActionView:: MissingTemplate（因为我们没有）。此时我们可以通过捕获 ActionView::MissingTemplate 看到渲染 :json 和 :xml(api_behaviour) 的实现。

现在我们知道 respond_with 是如何工作的，但 AR Logger 不知道.. cleanup_view_runtime hook 被调用了两次：for default_renderer（当时模板数据已经准备好并调用了一些数据库查询，但是我们在渲染过程中捕获了 ActionView::MissingTemplate）

db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime
runtime = super # <-- here
db_rt_after_render = ActiveRecord::LogSubscriber.reset_runtime

对于 api_behavour（当时所有模板数据都已准备好渲染，没有 db 查询）

一些混乱的解释，但我希望它会有所帮助:)

【讨论】：

是的，德米特里，调试器今天帮我找到了它，你有没有看到解决方案的问题，我在一小时前做的 github.com/rails/rails/issues/9215 所以现在我想了解 Rails 的哪些部分有通知测试赏金应该是你的！无论如何，我很感激:)【参考方案2】：

Rails 检测通过在机架金属级别包装请求并记录不同指标的事件来工作。在这两种情况下，整个块都应该被标准仪器包装和跟踪。

在深入研究源代码后我能看到的唯一区别是调用 save() 与 save!()。看起来 ActiveRecord 中的底层方法事件订阅可能会有不同的行为。

尝试更改您的 respond_with() 示例以使用保存与保存！看看它是否正确记录了db_runtime？如果是这样，那就是 Rails 错误，您可以通过模仿保存来解决它！使用保存功能。

【讨论】：

我也很困惑。很抱歉没有成功。温菲尔德！帮助我了解发生了什么！））【参考方案3】：

更新：

这并不简单，需要一些调整..

除非你编写自己的 Railtie 来像 Active Record 这样挂钩，但它比复制 Active Record 的内容要复杂一些......