rails activesupport 通知 - 错误的数据库运行时值 [英] rails activesupport notifications - wrong db runtime value

问题描述

我正在尝试记录对我的 REST API 应用程序的请求.我为此使用了 rails 通知，就像这里 http://railscasts.com/剧集/249-notifications-in-rails-3

I'm trying to log requests for my REST API application. I'm using rails notifications for this , like here http://railscasts.com/episodes/249-notifications-in-rails-3

我无法理解如何解决 Rails 通知的一个问题.

I can't understand how to solve one problem with rails notifications.

我的初始化代码

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

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

However if I change controller action code to default scaffold

  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

这是什么原因，我如何修复它以使其在第一个示例中工作?谢谢！

What is the reason of that and how I can fix it to make it work in first example ? Thanks !

更新

 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 时，它似乎不起作用！有人能告诉我为什么吗?谢谢

It seems like it doesn't work when I use respond_with! Can someone tell me why? Thanks

推荐答案

好吧，看来是个 bug.让我们看看发生了什么:

Ok, it seems like a bug. Let see, what's going on:

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

First of all, we have AR railtie for controller action and its implementation for setting db_runtime by using cleanup_view_runtime hook

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 保存运行时数据.不错.

App calls controller action -> action doing some db queries and renders some stuff -> before and after rendering AR Logger saves runtime data. Good.

让我们看看respond_with的工作原理

Let see how works 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) 的实现.

It seems like too much code here, but you should see the callstack for this issue: respond_with -> self.class.responder.respond -> self.class.responder.to_format -> default_render -> default_renderer raise ActionView::MissingTemplate(because we don't have any). At this moment we can see implementation for rendering :json and :xml(api_behaviour) through catching ActionView::MissingTemplate.

现在我们知道respond_with是如何工作的，但AR Logger不知道..cleanup_view_runtime 钩子被调用两次:用于 default_renderer(当时模板数据准备好了，一些数据库查询被调用，但我们在渲染过程中捕获了 ActionView::MissingTemplate)

Now we know how respond_with works, but AR Logger does'nt know.. cleanup_view_runtime hook is called twice: for default_renderer(at that time template data was prepared and some db queries were called, but we catch ActionView::MissingTemplate in rendering proccess)

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

以及 api_behavour(当时所有模板数据都已准备好进行渲染并且没有数据库查询)

and for api_behavour(at that time all template data was ready for rendering and no db queries)

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

Some messy explanation, but I hope it will be helpful :)

这篇关于rails activesupport 通知 - 错误的数据库运行时值的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！