I've been wanted to know where some sql queries are coming from. I worked on a Rails app with some tests which have been executed slowly. In the log file I saw this request a bunch of time :
SELECT `roles`.* FROM `roles` INNER JOIN `users_roles` ON `roles`.`id` = `users_roles`.`role_id` WHERE `users_roles`.`user_id` = 8 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))
So I've decided to use a Ryan Bigg tips. I've included this snippet in my test suite :
ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, details|
if details[:sql] =~ /INNER JOIN .users_roles./
puts caller.join("\n")
puts "*" * 50
end
end
And this gived me this result :
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/fanout.rb:127:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/fanout.rb:127:in `finish'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/fanout.rb:46:in `block in finish'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/fanout.rb:46:in `each'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/fanout.rb:46:in `finish'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/instrumenter.rb:36:in `finish'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/instrumenter.rb:25:in `instrument'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract_adapter.rb:460:in `log'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:299:in `execute'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/mysql2_adapter.rb:231:in `execute'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/mysql2_adapter.rb:235:in `exec_query'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/database_statements.rb:336:in `select'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/query_cache.rb:70:in `select_all'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/querying.rb:39:in `find_by_sql'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation.rb:638:in `exec_queries'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/association_relation.rb:19:in `exec_queries'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation.rb:514:in `load'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation.rb:243:in `to_a'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/association_relation.rb:13:in `=='
/Users/Yann/.gem/ruby/2.1.5/gems/rolify-4.0.0/lib/rolify/role.rb:33:in `!='
/Users/Yann/.gem/ruby/2.1.5/gems/rolify-4.0.0/lib/rolify/role.rb:33:in `has_role?'
/Users/Yann/code/eternam/app/mailers/option_mailer.rb:13:in `block in send_created_notification'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation/query_methods.rb:251:in `block in select'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation/query_methods.rb:251:in `select'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/relation/query_methods.rb:251:in `select'
/Users/Yann/code/eternam/app/mailers/option_mailer.rb:13:in `send_created_notification'
/Users/Yann/.gem/ruby/2.1.5/gems/actionpack-4.2.0/lib/abstract_controller/base.rb:198:in `process_action'
/Users/Yann/.gem/ruby/2.1.5/gems/actionpack-4.2.0/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:88:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:88:in `_run_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:734:in `_run_process_action_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:81:in `run_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/actionpack-4.2.0/lib/abstract_controller/callbacks.rb:19:in `process_action'
/Users/Yann/.gem/ruby/2.1.5/gems/actionpack-4.2.0/lib/abstract_controller/base.rb:137:in `process'
/Users/Yann/.gem/ruby/2.1.5/gems/actionview-4.2.0/lib/action_view/rendering.rb:30:in `process'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/base.rb:596:in `block in process'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications.rb:164:in `block in instrument'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications.rb:164:in `instrument'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/base.rb:593:in `process'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/base.rb:584:in `initialize'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/message_delivery.rb:25:in `new'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/message_delivery.rb:25:in `__getobj__'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/message_delivery.rb:34:in `message'
/Users/Yann/.gem/ruby/2.1.5/gems/actionmailer-4.2.0/lib/action_mailer/message_delivery.rb:85:in `deliver_now'
/Users/Yann/code/eternam/app/models/option.rb:148:in `send_created_notification'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:427:in `block in make_lambda'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:225:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:225:in `block in halting_and_conditional'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:92:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:92:in `_run_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:734:in `_run_create_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/callbacks.rb:306:in `_create_record'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/timestamp.rb:57:in `_create_record'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/persistence.rb:501:in `create_or_update'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/callbacks.rb:302:in `block in create_or_update'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:117:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:117:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:169:in `block in halting'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:169:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:169:in `block in halting'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:169:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:169:in `block in halting'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:92:in `call'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:92:in `_run_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/callbacks.rb:734:in `_run_save_callbacks'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/callbacks.rb:302:in `create_or_update'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/persistence.rb:142:in `save!'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/validations.rb:43:in `save!'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/attribute_methods/dirty.rb:29:in `save!'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/transactions.rb:291:in `block in save!'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/transactions.rb:347:in `block in with_transaction_returning_status'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `block in transaction'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/transaction.rb:188:in `within_new_transaction'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/transactions.rb:220:in `transaction'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/transactions.rb:344:in `with_transaction_returning_status'
/Users/Yann/.gem/ruby/2.1.5/gems/activerecord-4.2.0/lib/active_record/transactions.rb:291:in `save!'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/configuration.rb:14:in `block in initialize'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/evaluation.rb:15:in `[]'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/evaluation.rb:15:in `create'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/strategy/create.rb:12:in `block in result'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/strategy/create.rb:9:in `tap'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/strategy/create.rb:9:in `result'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/factory.rb:42:in `run'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/factory_runner.rb:23:in `block in run'
/Users/Yann/.gem/ruby/2.1.5/gems/activesupport-4.2.0/lib/active_support/notifications.rb:166:in `instrument'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/factory_runner.rb:22:in `run'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/strategy_syntax_method_registrar.rb:20:in `block in define_singular_strategy_method'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/linter.rb:25:in `block in calculate_invalid_factories'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/registry.rb:17:in `each'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/registry.rb:17:in `each'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/decorator.rb:10:in `inject'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/decorator.rb:10:in `method_missing'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/linter.rb:23:in `calculate_invalid_factories'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/linter.rb:9:in `initialize'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/linter.rb:4:in `new'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl/linter.rb:4:in `lint!'
/Users/Yann/.gem/ruby/2.1.5/gems/factory_girl-4.5.0/lib/factory_girl.rb:59:in `lint'
/Users/Yann/code/eternam/spec/rails_helper.rb:24:in `block (2 levels) in <top (required)>'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/example.rb:333:in `instance_exec'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/example.rb:333:in `instance_exec'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/hooks.rb:357:in `run'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/configuration.rb:1559:in `block in run_hooks_with'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/configuration.rb:1559:in `each'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/configuration.rb:1559:in `run_hooks_with'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/configuration.rb:1525:in `with_suite_hooks'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/runner.rb:109:in `block in run_specs'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/reporter.rb:62:in `report'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/runner.rb:108:in `run_specs'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/runner.rb:86:in `run'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/runner.rb:70:in `run'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/lib/rspec/core/runner.rb:38:in `invoke'
/Users/Yann/.gem/ruby/2.1.5/gems/rspec-core-3.2.0/exe/rspec:4:in `<top (required)>'
/Users/Yann/.gem/ruby/2.1.5/bin/rspec:23:in `load'
/Users/Yann/.gem/ruby/2.1.5/bin/rspec:23:in `<main>'
**************************************************
```
With the culprit in the middle :
... /Users/Yann/code/eternam/app/mailers/option_mailer.rb:13:in `block in send_created_notification' ...