Ruby on Rails | Screencasts | Download | Documentation | Weblog | Community | Source

Ticket #10475 (reopened defect)

Opened 2 years ago

Last modified 2 years ago

AbstractAdapter#log should benchmark queries regardless of log level

Reported by: brynary Assigned to: core
Priority: low Milestone: 2.x
Component: ActiveRecord Version: edge
Severity: minor Keywords:
Cc: xaviershay

Description

Currently, AbstractAdapter#log will not record query runtime if logger.debug? returns false. Because these query times are essential to calculating the total DB time for a request, this can lead to inaccurate information in production.log like: 

Completed in 0.23365 (4 reqs/sec) | Rendering: 0.05984 (25%) | DB: 0.00000 (0%) | 200 OK [http://localhost/...]

This patch simplifies the #log method by removing the check for the logger level (this check is already performed in #log_info, which it calls) and also adds tests for both #log and #log_level.

Attachments

always_benchmark_queries.patch (3.5 kB) - added by brynary on 12/11/07 20:14:21.
always_benchmark_db_time.diff (3.5 kB) - added by brynary on 04/07/08 21:28:19.
Updated to apply against latest trunk

Change History

12/11/07 20:14:21 changed by brynary

  • attachment always_benchmark_queries.patch added.

12/11/07 23:01:53 changed by marcel

  • status changed from new to closed.
  • resolution set to wontfix.

This is a clearly presented patch and it is well tested which is appreciated. Benchmarking, though, has been benchmarked :) and it's actually quite expensive. So that code was intentionally added for performance reasons. Perhaps the appropriate fix (if anything), in this case, would be to make the logger indicate that database benchmarks are not being calculated rather than misleading you into thinking the database is executing in no time at all.

12/12/07 06:56:25 changed by brynary

Marcel,

Looks like the conditional was added in r227. Can you (or perhaps someone else with knowledge of that decision) give some more information led to the conclusion the benchmarking was too slow?

If there's a faster way to benchmark, I'd like to explore that so the DB runtimes can be maintained consistently. If not, I'll prepare a patch to log appropriately when DB runtimes are not tracked.

In either case, I'll modify this patch to be test-only for the existing code so it can be applied.

WDYT?

-Bryan

12/12/07 20:43:28 changed by marcel

David is who you'd want to ask for benchmarking details about. He's the one who committed that revision (as you can see) and is the one who told me yesterday why it was there when I asked about it.

In the mean time, I agree that modifying the patch to be test-only for the existing code is a great idea. Please reopen when/if that gets done. Thanks.

12/20/07 00:56:26 changed by xaviershay

  • cc set to xaviershay.

02/05/08 19:48:08 changed by arthur.petry

For me, the conditionnal was added here : [8162]

And IMHO the message in this changeset is wrong ("Use debug, not info as log_info will discard the information if info is used. ") :

of course the information is not used in log_info, but the value of @runtime can be used elsewhere.

02/29/08 02:29:21 changed by vanharen

Given that benchmarking was improved drastically in changeset [8771], perhaps this should be revisited, and changeset [8162] reverted?

Benchmarking was expensive previously, but no longer is nearly as expensive. Removing the DB profiling from the logs is counter-productive -- it was done in the name of performance, but it denies us a powerful performance analysis tool.

04/07/08 21:28:19 changed by brynary

  • attachment always_benchmark_db_time.diff added.

Updated to apply against latest trunk

04/07/08 21:31:38 changed by brynary

  • status changed from closed to reopened.
  • resolution deleted.

Since the significant optimization to Benchmark.realtime was committed in r8771, I'd like to suggest that this patch be reconsidered in the interest of providing a valuable piece of performance information in the production logs.

04/24/08 21:21:04 changed by swindsor

This is ridiculous. I'm sorry, but there's already benchmarking done for rendering times for the default log levels, but the database benchmarking showing up as 0.0000 doesn't make any sense. If benchmarking is a performance concern then it should be a configurable option to disable the benchmark calls (which would include *all* benchmark calls, including render time).