diff --git a/CHANGELOG.md b/CHANGELOG.md index 5c25529f..fde8501d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - [FIX] Truncate long profiler name in profiler popup. [#634](https://github.com/MiniProfiler/rack-mini-profiler/pull/634) - [FIX] `flamegraph_mode` query param having no effect. [#635](https://github.com/MiniProfiler/rack-mini-profiler/pull/635) - [FEATURE] Show record type and count in SQL query UI. [#638](https://github.com/MiniProfiler/rack-mini-profiler/pull/638) +- [FEATURE] Show Active Record QueryCache hits in UI. [#640](https://github.com/MiniProfiler/rack-mini-profiler/pull/640) ## 3.3.1 - 2024-02-15 - [FEATURE] Support dynamic `config.content_security_policy_nonce` [#609](https://github.com/MiniProfiler/rack-mini-profiler/pull/609) diff --git a/lib/html/includes.css b/lib/html/includes.css index 64d157bb..055f273a 100644 --- a/lib/html/includes.css +++ b/lib/html/includes.css @@ -133,19 +133,21 @@ .profiler-result .profiler-timings .profiler-queries-duration { padding-left: 6px; } .profiler-result .profiler-timings .profiler-percent-in-sql { - white-space: nowrap; - text-align: right; } - .profiler-result .profiler-timings tfoot td { - padding-top: 10px; + white-space: nowrap; } + .profiler-result .profiler-timings tfoot tr td:last-child { text-align: right; } - .profiler-result .profiler-timings tfoot td a { + .profiler-result .profiler-timings-summary { + display: flex; + justify-content: space-between; + padding-top: 10px; } + .profiler-result .profiler-timings-summary a { font-size: 95%; display: inline-block; margin-left: 12px; } - .profiler-result .profiler-timings tfoot td a:first-child { + .profiler-result .profiler-timings-summary a:first-child { float: left; margin-left: 0px; } - .profiler-result .profiler-timings tfoot td a.profiler-custom-link { + .profiler-result .profiler-timings-summary a.profiler-custom-link { float: left; } .profiler-result .profiler-queries { font-family: Helvetica, Arial, sans-serif; } @@ -163,6 +165,12 @@ background-color: #fdd; } .profiler-result .profiler-queries tr.very-very-slow { background-color: #fcc; } + .profiler-result .profiler-queries tr.cached { + background-color: #f2f0ef; } + .profiler-result .profiler-queries span.cached { + color: #818589; } + .profiler-result .profiler-queries span.cached + pre { + display: inline; } .profiler-result .profiler-queries pre { font-family: Consolas, monospace, serif; white-space: pre-wrap; } diff --git a/lib/html/includes.js b/lib/html/includes.js index 4b57ad9f..7a476460 100644 --- a/lib/html/includes.js +++ b/lib/html/includes.js @@ -1288,6 +1288,10 @@ var _MiniProfiler = (function() { sqlTiming.parent_timing_name = timing.name; + if (sqlTiming.cached) { + sqlTiming.row_class = "cached"; + } + if (sqlTiming.duration_milliseconds > 50) { sqlTiming.row_class = "slow"; } diff --git a/lib/html/includes.scss b/lib/html/includes.scss index f3476d96..59f918d4 100644 --- a/lib/html/includes.scss +++ b/lib/html/includes.scss @@ -147,27 +147,28 @@ $zindex: 2147483640; // near 32bit max 2147483647 } .profiler-percent-in-sql { white-space: nowrap; + } + tfoot tr td:last-child { text-align: right; } + } - tfoot { - td { - padding-top: 10px; - text-align: right; + .profiler-timings-summary { + display: flex; + justify-content: space-between; + padding-top: 10px; - a { - font-size: 95%; - display: inline-block; - margin-left: 12px; + a { + font-size: 95%; + display: inline-block; + margin-left: 12px; - &:first-child { - float: left; - margin-left: 0px; - } - &.profiler-custom-link { - float: left; - } - } + &:first-child { + float: left; + margin-left: 0px; + } + &.profiler-custom-link { + float: left; } } } @@ -202,6 +203,18 @@ $zindex: 2147483640; // near 32bit max 2147483647 background-color: #fcc; } + tr.cached { + background-color: #f2f0ef; + } + + span.cached { + color: #818589; + } + + span.cached + pre { + display: inline; + } + pre { font-family: $codeFonts; white-space: pre-wrap; diff --git a/lib/html/includes.tmpl b/lib/html/includes.tmpl index 993a8639..8a4cec9e 100644 --- a/lib/html/includes.tmpl +++ b/lib/html/includes.tmpl @@ -45,33 +45,42 @@ {{= MiniProfiler.templates.timingTemplate({timing: it.root, page: it}) }} - - - - {{? !it.client_timings}} - {{= MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) }} - {{?}} - show time with children - snapshots - - {{? it.has_sql_timings}} - - {{= MiniProfiler.formatDuration(it.duration_milliseconds_in_sql / it.duration_milliseconds * 100) }} - % in sql + {{? it.has_sql_timings}} + + + + SQL Summary: - {{?}} - {{~ it.custom_timing_names :value}} - - {{= MiniProfiler.formatDuration(it.custom_timing_stats[value].duration / it.duration_milliseconds * 100) }} - % in {{= value.toLowerCase() }} + + {{=it.sql_count}} {{? it.cached_sql_count > 0 }} ({{=it.cached_sql_count}} cached) {{?}} + - + {{= MiniProfiler.formatDuration(it.duration_milliseconds_in_sql / it.duration_milliseconds * 100) }}% in sql + - {{~}} - - + + + {{?}} + +
+
+ {{? !it.client_timings}} + {{= MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) }} + {{?}} + show time with children + snapshots +
+ {{~ it.custom_timing_names :value}} +
+ {{= MiniProfiler.formatDuration(it.custom_timing_stats[value].duration / it.duration_milliseconds * 100) }} + % in {{= value.toLowerCase() }} +
+ {{~}} +
+ {{? it.client_timings}} @@ -230,6 +239,9 @@
{{= it.s.stack_trace_snippet }}
+ {{? it.s.cached }} + [CACHE] + {{?}} {{? it.s.formatted_command_string}}
{{= it.s.formatted_command_string }}; {{= MiniProfiler.formatParameters(it.s.parameters) }}
{{??}} diff --git a/lib/html/vendor.js b/lib/html/vendor.js index 80927fa0..d8c2c3d6 100644 --- a/lib/html/vendor.js +++ b/lib/html/vendor.js @@ -7,7 +7,7 @@ MiniProfiler.templates = {}; MiniProfiler.templates["profilerTemplate"] = function anonymous(it ) { -var out='
';if(it.has_duplicate_sql_timings){out+='!';}out+=' '+( MiniProfiler.formatDuration(it.duration_milliseconds))+' ms ';if(MiniProfiler.showTotalSqlCount()){out+=' '+( it.sql_count)+' sql ';}out+=' ';if(it.name.length >= 30){out+=' '+( it.name.substring(0,15) + "..." + it.name.slice(-15) )+' ';}else{out+=' '+( it.name)+' ';}out+='
'+( it.name )+' ('+( MiniProfiler.formatDuration(it.duration_milliseconds))+' ms) '+( it.machine_name)+' on '+( MiniProfiler.renderDate(it.started_formatted))+'
';if(it.has_sql_timings){out+=' ';}out+=' ';var arr1=it.custom_timing_names;if(arr1){var value,i1=-1,l1=arr1.length-1;while(i1'+( value.toLowerCase() )+' (ms) ';} } out+=' '+( MiniProfiler.templates.timingTemplate({timing: it.root, page: it}) )+' ';if(it.has_sql_timings){out+=' ';}out+=' ';var arr2=it.custom_timing_names;if(arr2){var value,i2=-1,l2=arr2.length-1;while(i2 '+( MiniProfiler.formatDuration(it.custom_timing_stats[value].duration / it.duration_milliseconds * 100) )+' % in '+( value.toLowerCase() )+' ';} } out+='
event duration (ms) with children (ms) from start (ms)query time (ms)
';if(!it.client_timings){out+=' '+( MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) )+' ';}out+=' show time with children snapshots '+( MiniProfiler.formatDuration(it.duration_milliseconds_in_sql / it.duration_milliseconds * 100) )+' % in sql
';if(it.client_timings){out+=' ';var arr3=MiniProfiler.getClientTimings(it.client_timings);if(arr3){var value,i3=-1,l3=arr3.length-1;while(i3 ';} } out+='
client event duration (ms) from start (ms)
'+( value.name )+' ';if(value.duration >= 0){out+=' '+( MiniProfiler.formatDuration(value.duration) )+' ';}out+=' +'+( MiniProfiler.formatDuration(value.start) )+'
'+( MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) )+'
';}out+=' ';if(it.custom_fields && Object.keys(it.custom_fields).length > 0){out+='

Snapshot custom fields

';var arr4=Object.keys(it.custom_fields);if(arr4){var key,i4=-1,l4=arr4.length-1;while(i4 ';} } out+='
'+( key )+' '+( it.custom_fields[key] )+'
';}out+='
';if(it.has_sql_timings){out+='
';var arr5=MiniProfiler.getSqlTimings(it.root);if(arr5){var value,index=-1,l5=arr5.length-1;while(indexms ';if(MiniProfiler.showTotalSqlCount()){out+=' '+( it.sql_count)+' sql ';}out+=' ';if(it.name.length >= 30){out+=' '+( it.name.substring(0,15) + "..." + it.name.slice(-15) )+' ';}else{out+=' '+( it.name)+' ';}out+='
'+( it.name )+' ('+( MiniProfiler.formatDuration(it.duration_milliseconds))+' ms) '+( it.machine_name)+' on '+( MiniProfiler.renderDate(it.started_formatted))+'
step
time from start
query type
duration
records
call stack
query
';if(it.has_sql_timings){out+=' ';}out+=' ';var arr1=it.custom_timing_names;if(arr1){var value,i1=-1,l1=arr1.length-1;while(i1'+( value.toLowerCase() )+' (ms) ';} } out+=' '+( MiniProfiler.templates.timingTemplate({timing: it.root, page: it}) )+' ';if(it.has_sql_timings){out+=' ';}out+='
event duration (ms) with children (ms) from start (ms)query time (ms)
SQL Summary: '+(it.sql_count)+' ';if(it.cached_sql_count > 0){out+=' ('+(it.cached_sql_count)+' cached) ';}out+=' - '+( MiniProfiler.formatDuration(it.duration_milliseconds_in_sql / it.duration_milliseconds * 100) )+'% in sql
';if(!it.client_timings){out+=' '+( MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) )+' ';}out+=' show time with children snapshots
';var arr2=it.custom_timing_names;if(arr2){var value,i2=-1,l2=arr2.length-1;while(i2 '+( MiniProfiler.formatDuration(it.custom_timing_stats[value].duration / it.duration_milliseconds * 100) )+' % in '+( value.toLowerCase() )+'
';} } out+='
';if(it.client_timings){out+=' ';var arr3=MiniProfiler.getClientTimings(it.client_timings);if(arr3){var value,i3=-1,l3=arr3.length-1;while(i3 ';} } out+='
client event duration (ms) from start (ms)
'+( value.name )+' ';if(value.duration >= 0){out+=' '+( MiniProfiler.formatDuration(value.duration) )+' ';}out+=' +'+( MiniProfiler.formatDuration(value.start) )+'
'+( MiniProfiler.templates.linksTemplate({timing: it.root, page: it}) )+'
';}out+=' ';if(it.custom_fields && Object.keys(it.custom_fields).length > 0){out+='

Snapshot custom fields

';var arr4=Object.keys(it.custom_fields);if(arr4){var key,i4=-1,l4=arr4.length-1;while(i4 ';} } out+='
'+( key )+' '+( it.custom_fields[key] )+'
';}out+='
';if(it.has_sql_timings){out+='
';var arr5=MiniProfiler.getSqlTimings(it.root);if(arr5){var value,index=-1,l5=arr5.length-1;while(index ';return out; +var out=' ';return out; } MiniProfiler.templates["sqlGapTemplate"] = function anonymous(it ) { diff --git a/lib/mini_profiler/asset_version.rb b/lib/mini_profiler/asset_version.rb index b1c1eba4..5617a77d 100644 --- a/lib/mini_profiler/asset_version.rb +++ b/lib/mini_profiler/asset_version.rb @@ -1,6 +1,6 @@ # frozen_string_literal: true module Rack class MiniProfiler - ASSET_VERSION = 'f1a9e67b901ae71247f42690c041ea35' + ASSET_VERSION = '6b13136c854b67ed12d949d9a599d925' end end diff --git a/lib/mini_profiler/profiling_methods.rb b/lib/mini_profiler/profiling_methods.rb index 78d0dda0..3fc2dd30 100644 --- a/lib/mini_profiler/profiling_methods.rb +++ b/lib/mini_profiler/profiling_methods.rb @@ -4,7 +4,7 @@ module Rack class MiniProfiler module ProfilingMethods - def record_sql(query, elapsed_ms, params = nil) + def record_sql(query, elapsed_ms, params = nil, cached = nil) return unless current && current.current_timer c = current c.current_timer.add_sql( @@ -13,7 +13,8 @@ def record_sql(query, elapsed_ms, params = nil) c.page_struct, redact_sql_queries? ? nil : params, c.skip_backtrace, - c.full_backtrace + c.full_backtrace, + cached ) end diff --git a/lib/mini_profiler/timer_struct/page.rb b/lib/mini_profiler/timer_struct/page.rb index d32d28e8..cb613a40 100644 --- a/lib/mini_profiler/timer_struct/page.rb +++ b/lib/mini_profiler/timer_struct/page.rb @@ -78,6 +78,7 @@ def initialize(env) trivial_duration_threshold_milliseconds: 2, head: nil, sql_count: 0, + cached_sql_count: 0, duration_milliseconds_in_sql: 0, has_sql_timings: true, has_duplicate_sql_timings: false, diff --git a/lib/mini_profiler/timer_struct/request.rb b/lib/mini_profiler/timer_struct/request.rb index 940d0b38..20411987 100644 --- a/lib/mini_profiler/timer_struct/request.rb +++ b/lib/mini_profiler/timer_struct/request.rb @@ -101,14 +101,15 @@ def move_child(child, destination) end end - def add_sql(query, elapsed_ms, page, params = nil, skip_backtrace = false, full_backtrace = false) - TimerStruct::Sql.new(query, elapsed_ms, page, self, params, skip_backtrace, full_backtrace).tap do |timer| + def add_sql(query, elapsed_ms, page, params = nil, skip_backtrace = false, full_backtrace = false, cached = false) + TimerStruct::Sql.new(query, elapsed_ms, page, self, params, skip_backtrace, full_backtrace, cached).tap do |timer| self[:sql_timings].push(timer) timer[:parent_timing_id] = self[:id] self[:has_sql_timings] = true self[:sql_timings_duration_milliseconds] += elapsed_ms page[:duration_milliseconds_in_sql] += elapsed_ms page[:sql_count] += 1 + page[:cached_sql_count] += 1 if cached end end diff --git a/lib/mini_profiler/timer_struct/sql.rb b/lib/mini_profiler/timer_struct/sql.rb index 5ba150d4..5a28fa34 100644 --- a/lib/mini_profiler/timer_struct/sql.rb +++ b/lib/mini_profiler/timer_struct/sql.rb @@ -10,7 +10,7 @@ module TimerStruct class Sql < TimerStruct::Base attr_accessor :parent - def initialize(query, duration_ms, page, parent, params = nil, skip_backtrace = false, full_backtrace = false) + def initialize(query, duration_ms, page, parent, params = nil, skip_backtrace = false, full_backtrace = false, cached = false) stack_trace = nil unless skip_backtrace || duration_ms < Rack::MiniProfiler.config.backtrace_threshold_ms @@ -49,6 +49,7 @@ def initialize(query, duration_ms, page, parent, params = nil, skip_backtrace = row_count: 0, class_name: nil, parent_timing_id: nil, + cached: cached, is_duplicate: false ) end diff --git a/lib/mini_profiler_rails/railtie.rb b/lib/mini_profiler_rails/railtie.rb index 57379962..b3f2c8cb 100644 --- a/lib/mini_profiler_rails/railtie.rb +++ b/lib/mini_profiler_rails/railtie.rb @@ -111,7 +111,8 @@ def self.initialize!(app) Rack::MiniProfiler.record_sql( payload[:sql], (finish - start) * 1000, - Rack::MiniProfiler.binds_to_params(payload[:binds]) + Rack::MiniProfiler.binds_to_params(payload[:binds]), + payload[:cached] ) end diff --git a/spec/lib/timer_struct/request_timer_struct_spec.rb b/spec/lib/timer_struct/request_timer_struct_spec.rb index eb05266f..5e09cbf4 100644 --- a/spec/lib/timer_struct/request_timer_struct_spec.rb +++ b/spec/lib/timer_struct/request_timer_struct_spec.rb @@ -60,10 +60,11 @@ def origin_and_destination(req) end describe 'add SQL' do + let(:params) { ["SELECT 1 FROM users", 77, @page] } before do @page = new_page - @request.add_sql("SELECT 1 FROM users", 77, @page) + @request.add_sql(*params) end it 'has a true HasSqlTimings attribute' do @@ -82,10 +83,21 @@ def origin_and_destination(req) expect(@request[:sql_timings_duration_milliseconds]).to eq(77) end - it "increases the page's " do + it "increases the page's duration_milliseconds_in_sql" do expect(@page[:duration_milliseconds_in_sql]).to eq(77) end + it "does not increment the page's cached_sql_count" do + expect(@page[:cached_sql_count]).to eq(0) + end + + context "with cached sql query" do + let(:params) { ["SELECT 1 FROM users", 77, @page, nil, false, false, true] } + + it "increments the page's cached_sql_count" do + expect(@page[:cached_sql_count]).to eq(1) + end + end end describe 'add Custom' do diff --git a/spec/lib/timer_struct/sql_timer_struct_spec.rb b/spec/lib/timer_struct/sql_timer_struct_spec.rb index f0b98477..442c8a1d 100644 --- a/spec/lib/timer_struct/sql_timer_struct_spec.rb +++ b/spec/lib/timer_struct/sql_timer_struct_spec.rb @@ -7,12 +7,12 @@ describe 'valid sql timer' do before do - @sql = Rack::MiniProfiler::TimerStruct::Sql.new("SELECT * FROM users", 200, @page, nil) + @sql = Rack::MiniProfiler::TimerStruct::Sql.new("SELECT * FROM users", 200, @page, nil, true) end [ :execute_type, :formatted_command_string, :stack_trace_snippet, :start_milliseconds, :duration_milliseconds, - :first_fetch_duration_milliseconds, :is_duplicate + :first_fetch_duration_milliseconds, :is_duplicate, :cached ].each do |attr_type| it "has an #{attr_type}" do expect(@sql[attr_type]).not_to be_nil
step
time from start
query type
duration
records
call stack
query
'+( it.s.parent_timing_name )+'
T+'+( MiniProfiler.formatDuration(it.s.start_milliseconds) )+' ms
';if(it.s.is_duplicate){out+='DUPLICATE';}out+=' '+( MiniProfiler.renderExecuteType(it.s.execute_type) )+'
'+( MiniProfiler.formatDuration(it.s.duration_milliseconds) )+' ms
';if(it.s.row_count > 0){out+='
'+( it.s.class_name )+': '+( it.s.row_count )+'
';}out+='
'+( it.s.stack_trace_snippet )+'
';if(it.s.formatted_command_string){out+='
'+( it.s.formatted_command_string )+'; '+( MiniProfiler.formatParameters(it.s.parameters) )+'
';}else{out+=' Query redacted ';}out+='
'+( it.s.parent_timing_name )+'
T+'+( MiniProfiler.formatDuration(it.s.start_milliseconds) )+' ms
';if(it.s.is_duplicate){out+='DUPLICATE';}out+=' '+( MiniProfiler.renderExecuteType(it.s.execute_type) )+'
'+( MiniProfiler.formatDuration(it.s.duration_milliseconds) )+' ms
';if(it.s.row_count > 0){out+='
'+( it.s.class_name )+': '+( it.s.row_count )+'
';}out+='
'+( it.s.stack_trace_snippet )+'
';if(it.s.cached){out+=' [CACHE] ';}out+=' ';if(it.s.formatted_command_string){out+='
'+( it.s.formatted_command_string )+'; '+( MiniProfiler.formatParameters(it.s.parameters) )+'
';}else{out+=' Query redacted ';}out+='