Skip to content

Commit 80e3b2a

Browse files
authored
Merge pull request rails#54066 from benkoshy/docs-rails-guide-verbose-query-logs
docs: rails debug guide - add detail re: verbose logs [ci-skip]
2 parents f75dff4 + eac0eec commit 80e3b2a

File tree

2 files changed

+40
-42
lines changed

2 files changed

+40
-42
lines changed

guides/source/7_1_release_notes.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -866,7 +866,7 @@ Please refer to the [Changelog][active-job] for detailed changes.
866866

867867
* Add `after_discard` method to `ActiveJob::Base` to run a callback when a job is about to be discarded.
868868

869-
* Add support for logging background job enqueue callers.
869+
* Add support for logging background job enqueue callers via `config.active_job.verbose_enqueue_logs`.
870870

871871
Action Text
872872
----------

guides/source/debugging_rails_applications.md

Lines changed: 39 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -107,22 +107,14 @@ It can also be useful to save information to log files at runtime. Rails maintai
107107

108108
### What is the Logger?
109109

110-
Rails makes use of the `ActiveSupport::Logger` class to write log information. Other loggers, such as `Log4r`, may also be substituted.
111-
112-
You can specify an alternative logger in `config/application.rb` or any other environment file, for example:
110+
Rails makes use of the `ActiveSupport::Logger` class to write log information. Other loggers, such as `Log4r`, may be substituted:
113111

114112
```ruby
113+
# config/environments/production.rb
115114
config.logger = Logger.new(STDOUT)
116115
config.logger = Log4r::Logger.new("Application Log")
117116
```
118117

119-
Or in the `Initializer` section, add _any_ of the following
120-
121-
```ruby
122-
Rails.logger = Logger.new(STDOUT)
123-
Rails.logger = Log4r::Logger.new("Application Log")
124-
```
125-
126118
TIP: By default, each log is created under `Rails.root/log/` and the log file is named after the environment in which the application is running.
127119

128120
### Log Levels
@@ -134,11 +126,11 @@ method.
134126

135127
The available log levels are: `:debug`, `:info`, `:warn`, `:error`, `:fatal`,
136128
and `:unknown`, corresponding to the log level numbers from 0 up to 5,
137-
respectively. To change the default log level, use
129+
respectively. To change the default log level:
138130

139131
```ruby
140-
config.log_level = :warn # In any environment initializer, or
141-
Rails.logger.level = 0 # at any time
132+
# config/environments/production.rb
133+
config.log_level = :warn
142134
```
143135

144136
This is useful when you want to log under development or staging without flooding your production log with unnecessary information.
@@ -217,7 +209,7 @@ irb(main):001:0> Article.pamplemousse
217209
=> #<Comment id: 2, author: "1", body: "Well, actually...", article_id: 1, created_at: "2018-10-19 00:56:10", updated_at: "2018-10-19 00:56:10">
218210
```
219211

220-
After running `ActiveRecord.verbose_query_logs = true` in the `bin/rails console` session to enable verbose query logs and running the method again, it becomes obvious what single line of code is generating all these discrete database calls:
212+
After enabling `verbose_query_logs` we can see additional information for each query:
221213

222214
```irb
223215
irb(main):003:0> Article.pamplemousse
@@ -232,23 +224,31 @@ irb(main):003:0> Article.pamplemousse
232224
=> #<Comment id: 2, author: "1", body: "Well, actually...", article_id: 1, created_at: "2018-10-19 00:56:10", updated_at: "2018-10-19 00:56:10">
233225
```
234226

235-
Below each database statement you can see arrows pointing to the specific source filename (and line number) of the method that resulted in a database call. This can help you identify and address performance problems caused by N+1 queries: single database queries that generates multiple additional queries.
227+
Below each database statement you can see arrows pointing to the specific source filename (and line number) of the method that resulted in a database call e.g. `↳ app/models/article.rb:5`.
228+
229+
This can help you identify and address performance problems caused by N+1 queries: i.e. single database queries that generate multiple additional queries.
236230

237-
Verbose query logs are enabled by default in the development environment logs after Rails 5.2.
231+
Verbose query logs are [enabled by default](configuring.html#config-active-record-verbose-query-logs) in the development environment logs.
238232

239233
WARNING: We recommend against using this setting in production environments. It relies on Ruby's `Kernel#caller` method which tends to allocate a lot of memory in order to generate stacktraces of method calls. Use query log tags (see below) instead.
240234

241235
### Verbose Enqueue Logs
242236

243237
Similar to the "Verbose Query Logs" above, allows to print source locations of methods that enqueue background jobs.
244238

245-
It is enabled by default in development. To enable in other environments, add in `application.rb` or any environment initializer:
239+
Verbose enqueue logs are [enabled by default](/7_1_release_notes.html#active-job-notable-changes) in the development environment logs.
246240

247-
```rb
241+
```ruby
242+
# config/environments/development.rb
248243
config.active_job.verbose_enqueue_logs = true
249244
```
250245

251-
As verbose query logs, it is not recommended for use in production environments.
246+
```irb
247+
# bin/rails console
248+
ActiveJob.verbose_enqueue_logs = true
249+
```
250+
251+
WARNING: We recommend against using this setting in production environments.
252252

253253
SQL Query Comments
254254
------------------
@@ -258,9 +258,7 @@ trace troublesome queries back to the area of the application that generated the
258258
logging slow queries (e.g. [MySQL](https://dev.mysql.com/doc/refman/en/slow-query-log.html), [PostgreSQL](https://www.postgresql.org/docs/current/runtime-config-logging.html#GUC-LOG-MIN-DURATION-STATEMENT)),
259259
viewing currently running queries, or for end-to-end tracing tools.
260260

261-
To enable, add in `application.rb` or any environment initializer:
262-
263-
```rb
261+
```ruby
264262
config.active_record.query_log_tags_enabled = true
265263
```
266264

@@ -351,7 +349,7 @@ By default, a debugging session will start after the `debug` library is required
351349

352350
To enter the debugging session, you can use `binding.break` and its aliases: `binding.b` and `debugger`. The following examples will use `debugger`:
353351

354-
```rb
352+
```ruby
355353
class PostsController < ApplicationController
356354
before_action :set_post, only: %i[ show edit update destroy ]
357355
@@ -366,7 +364,7 @@ end
366364

367365
Once your app evaluates the debugging statement, it'll enter the debugging session:
368366

369-
```rb
367+
```ruby
370368
Processing by PostsController#index as HTML
371369
[2, 11] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
372370
2| before_action :set_post, only: %i[ show edit update destroy ]
@@ -391,7 +389,7 @@ You can exit the debugging session at any time and continue your application exe
391389

392390
After entering the debugging session, you can type in Ruby code as if you are in a Rails console or IRB.
393391

394-
```rb
392+
```ruby
395393
(rdbg) @posts # ruby
396394
[]
397395
(rdbg) self
@@ -401,7 +399,7 @@ After entering the debugging session, you can type in Ruby code as if you are in
401399

402400
You can also use the `p` or `pp` command to evaluate Ruby expressions, which is useful when a variable name conflicts with a debugger command.
403401

404-
```rb
402+
```ruby
405403
(rdbg) p headers # command
406404
=> {"X-Frame-Options"=>"SAMEORIGIN", "X-XSS-Protection"=>"1; mode=block", "X-Content-Type-Options"=>"nosniff", "X-Download-Options"=>"noopen", "X-Permitted-Cross-Domain-Policies"=>"none", "Referrer-Policy"=>"strict-origin-when-cross-origin"}
407405
(rdbg) pp headers # command
@@ -424,7 +422,7 @@ Besides direct evaluation, the debugger also helps you collect a rich amount of
424422

425423
`info` provides an overview of the values of local and instance variables that are visible from the current frame.
426424

427-
```rb
425+
```ruby
428426
(rdbg) info # command
429427
%self = #<PostsController:0x0000000000af78>
430428
@_action_has_layout = true
@@ -444,7 +442,7 @@ Besides direct evaluation, the debugger also helps you collect a rich amount of
444442

445443
When used without any options, `backtrace` lists all the frames on the stack:
446444

447-
```rb
445+
```ruby
448446
=>#0 PostsController#index at ~/projects/rails-guide-example/app/controllers/posts_controller.rb:7
449447
#1 ActionController::BasicImplicitRender#send_action(method="index", args=[]) at ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-2.0.alpha/lib/action_controller/metal/basic_implicit_render.rb:6
450448
#2 AbstractController::Base#process_action(method_name="index", args=[]) at ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-8.1.0.alpha/lib/abstract_controller/base.rb:214
@@ -484,7 +482,7 @@ It is also possible to use these options together: `backtrace [num] /pattern/`.
484482
- Class variables
485483
- Methods & their sources
486484

487-
```rb
485+
```ruby
488486
ActiveSupport::Configurable#methods: config
489487
AbstractController::Base#methods:
490488
action_methods action_name action_name= available_action? controller_path inspect
@@ -533,7 +531,7 @@ And to remove them, you can use:
533531

534532
**Set a breakpoint on a specified line number - e.g. `b 28`**
535533

536-
```rb
534+
```ruby
537535
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
538536
20| end
539537
21|
@@ -552,7 +550,7 @@ And to remove them, you can use:
552550
#0 BP - Line /Users/st0012/projects/rails-guide-example/app/controllers/posts_controller.rb:28 (line)
553551
```
554552

555-
```rb
553+
```ruby
556554
(rdbg) c # continue command
557555
[23, 32] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
558556
23| def create
@@ -574,7 +572,7 @@ Stop by #0 BP - Line /Users/st0012/projects/rails-guide-example/app/controller
574572

575573
Set a breakpoint on a given method call - e.g. `b @post.save`.
576574

577-
```rb
575+
```ruby
578576
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
579577
20| end
580578
21|
@@ -594,7 +592,7 @@ Set a breakpoint on a given method call - e.g. `b @post.save`.
594592

595593
```
596594

597-
```rb
595+
```ruby
598596
(rdbg) c # continue command
599597
[39, 48] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/suppressor.rb
600598
39| SuppressorRegistry.suppressed[name] = previous_state
@@ -618,7 +616,7 @@ Stop by #0 BP - Method @post.save at /Users/st0012/.rbenv/versions/3.0.1/lib/r
618616
619617
Stop when an exception is raised - e.g. `catch ActiveRecord::RecordInvalid`.
620618
621-
```rb
619+
```ruby
622620
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
623621
20| end
624622
21|
@@ -637,7 +635,7 @@ Stop when an exception is raised - e.g. `catch ActiveRecord::RecordInvalid`.
637635
#1 BP - Catch "ActiveRecord::RecordInvalid"
638636
```
639637
640-
```rb
638+
```ruby
641639
(rdbg) c # continue command
642640
[75, 84] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/validations.rb
643641
75| def default_validation_context
@@ -661,7 +659,7 @@ Stop by #1 BP - Catch "ActiveRecord::RecordInvalid"
661659

662660
Stop when the instance variable is changed - e.g. `watch @_response_body`.
663661

664-
```rb
662+
```ruby
665663
[20, 29] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
666664
20| end
667665
21|
@@ -680,7 +678,7 @@ Stop when the instance variable is changed - e.g. `watch @_response_body`.
680678
#0 BP - Watch #<PostsController:0x00007fce69ca5320> @_response_body =
681679
```
682680

683-
```rb
681+
```ruby
684682
(rdbg) c # continue command
685683
[173, 182] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/actionpack-7.0.0.alpha2/lib/action_controller/metal.rb
686684
173| body = [body] unless body.nil? || body.respond_to?(:each)
@@ -716,7 +714,7 @@ In addition to different types of breakpoints, you can also specify options to a
716714

717715
Please also note that the first 3 options: `do:`, `pre:` and `if:` are also available for the debug statements we mentioned earlier. For example:
718716

719-
```rb
717+
```ruby
720718
[2, 11] in ~/projects/rails-guide-example/app/controllers/posts_controller.rb
721719
2| before_action :set_post, only: %i[ show edit update destroy ]
722720
3|
@@ -750,7 +748,7 @@ Please also note that the first 3 options: `do:`, `pre:` and `if:` are also avai
750748

751749
With those options, you can script your debugging workflow in one line like:
752750

753-
```rb
751+
```ruby
754752
def create
755753
debugger(do: "catch ActiveRecord::RecordInvalid do: bt 10")
756754
# ...
@@ -759,7 +757,7 @@ end
759757

760758
And then the debugger will run the scripted command and insert the catch breakpoint
761759

762-
```rb
760+
```ruby
763761
(rdbg:binding.break) catch ActiveRecord::RecordInvalid do: bt 10
764762
#0 BP - Catch "ActiveRecord::RecordInvalid"
765763
[75, 84] in ~/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/activerecord-7.0.0.alpha2/lib/active_record/validations.rb
@@ -780,7 +778,7 @@ And then the debugger will run the scripted command and insert the catch breakpo
780778

781779
Once the catch breakpoint is triggered, it'll print the stack frames
782780

783-
```rb
781+
```ruby
784782
Stop by #0 BP - Catch "ActiveRecord::RecordInvalid"
785783

786784
(rdbg:catch) bt 10

0 commit comments

Comments
 (0)