This set of tasks scans a Ruby Logger file and tallies timestamps. It finds first timestamp and last timestamp recorded in the log and prints out start/start times, elapsed time, and the logfile it scanned. Additionally, if you use the Sequel gem and log SQL to the log file, it extracts the SQL, parameterizes those SQLs so we can group 'em and g…

log.rake

namespace :log do
  def timestamp line
    values = line.match(/(\d{4})\-(\d{2})\-(\d{2})T(\d{2})\:(\d{2})\:(\d{2}\.\d{6})/).captures
    Time.new(*values.map(&:to_f))
  end
    
  task :timestamps do
    Dir.glob(File.join(log_path, '*.log')).each do |fn|
      top = `head -n 2 #{fn}`.split("\n")
      top.shift if top[0] =~ /Logfile created/
      top = timestamp(top.first)
      bottom = timestamp(`tail -n 1 #{fn}`.split("\n").first)
      elapsed = (bottom - top)
      puts [top.strftime("%H:%M:%S.%6N"), bottom.strftime("%H:%M:%S.%6N"), elapsed.round(2), File.basename(fn)].join("\t")
    end
  end
  
  task :sql_stats do
    class SqlStmt 
      attr_reader :seconds, :sql, :sql_str
      
      def initialize line
        begin
          secs_str, @sql_str = line.match(/\((\d+\.\d+)s\)\s(.*)/).captures
          @seconds = secs_str.to_f
          @sql = @sql_str.gsub(/(?:(["'])|(“)|‘).*?(?<!\\)(?(1)\1|(?(2)”|’))/, '%s').
            gsub(/[\d|\.]+/, '%d').
            gsub(/N%s|N'[^\Z]+\Z/, '%s').
            gsub(/(%s)+/,'%s')
          @sql = @sql.scan(/\A[^%]+/).join if self.type == :execute
        end
      end
      
      def type
        return :execute if sql =~ /EXEC/
        return :select  if sql =~ /SELECT/
        return :update  if sql =~ /UPDATE/
        return :insert  if sql =~ /INSERT/
        return :delete  if sql =~ /DELETE/
        return :unknown
      end
      
      def to_s
        @sql
      end
      
      def <=> other
        self.sql <=> other.sql
      end
    end

    # Get all the SQL statements in the log files
    sql_stmts = []
    Dir.glob(File.join(log_path, '*.log')) do |log_filename|
      sql_stmts += File.read(log_filename).force_encoding(Encoding::UTF_8).split("\n").map do |line|
        if line =~ /INSERT|UPDATE|DELETE|SELECT/ && line.match(/\((\d+\.\d+)s\)\s(.*)/)
          SqlStmt.new line
        end
      end
    end

    # group 'em and sort 'em
    sql_stmts = sql_stmts.compact.group_by{|gb| gb.sql}.sort{|a,b| a.last.size <=> b.last.size}
    
    # show us what's eating up our time
    sql_stmts.each do |group, sql_stmts|
      all_seconds = sql_stmts.map(&:seconds).sort
      total_secs = all_seconds.inject{|seconds, sum| sum += seconds}.round(4)
      min_secs = all_seconds.min.round(4)
      max_secs = all_seconds.max.round(4)
      median = all_seconds[all_seconds.size / 2].round(4)
      mean = all_seconds.inject(0) { |x, sum| sum += x } / all_seconds.size.to_f
      puts [sql_stmts.first.type, sql_stmts.size, min_secs, max_secs, median, total_secs, group[0,125]].join("\t")
    end
  end
end

sample_output.txt

execute	4492	0.0	0.004	0.0001	0.5384	DECLARE @RC int; EXECUTE @RC = pr_update_item_bwk
select	5238	0.0	0.0058	0.0001	0.3498	SELECT [SA]%d[SUBJECT_ID], [SA]%d[ID] AS [ASSIGNED_ID], [S]%d[CODE] FROM [SUBJECTS] AS [S] INNER JOIN [SUBJECT_ASSIGNMENTS] A
delete	5348	0.0003	0.0143	0.0006	5.5723	DELETE FROM [AWARDS] WHERE ([ITEM_ID] = %d)
delete	5349	0.0005	0.0975	0.0013	16.6998	DELETE FROM [AUTHOR_PARTICIPATIONS] WHERE ([ITEM_ID] = %d)
select	5349	0.0	0.0062	0.0001	0.4129	SELECT TOP (%d) [ID] FROM [ITEMS] WHERE ([ID] = %d)
select	5349	0.0	0.0086	0.0001	0.4333	SELECT TOP (%d) [ID] FROM [UPDATE_LOCKS] WHERE (([TABLE_NAME] = %s) AND ([COLUMN_NAME] = %s))
select	5366	0.0	0.0022	0.0001	0.3584	SELECT TOP (%d) [ID] FROM [FORMAT_DETAILS] WITH (NOLOCK) WHERE ([CODE] = %s)
select	5401	0.0	0.003	0.0001	0.3435	SELECT TOP (%d) [ID] FROM [FORMATS] WITH (NOLOCK) WHERE ([CODE] = %s)
select	5418	0.0	0.0149	0.0001	0.3703	SELECT TOP (%d) [ID] FROM [DETAILED_FORMATS] WITH (NOLOCK) WHERE (([ITEM_ID] = %d) AND ([FORMAT_ID] = %d) AND ([FORMAT_DETAIL
select	6329	0.0	0.0144	0.0001	0.5436	SELECT TOP (%d) [PUBLISHER_ID] FROM [PUBLISHERS_UPDATE_LOCKS] WHERE (([UPDATE_LOCK_ID] = %d) AND ([PUBLISHER_ID] = %s))
update	6329	0.0007	0.1516	0.0021	28.472	UPDATE [PUBLISHERS] SET [NAME] = %s WHERE ([ID] = %d)
select	6329	0.0	0.0078	0.0001	0.515	SELECT TOP (%d) [ID] FROM [PUBLISHERS] WHERE ([BWK_UID] = %s)
update	6493	0.0004	0.029	0.0007	7.8107	UPDATE [OTHER_TXTS] SET [TXT_DATA] = %s WHERE ([ID] = %d)
select	6526	0.0	0.0132	0.0001	0.546	SELECT TOP (%d) [ID] FROM [ITEMS] WHERE (([ID] = %d) AND ([TRASH_TYPE_ID] = %d))
select	7684	0.0	0.0059	0.0001	0.5119	SELECT TOP (%d) [ID] FROM [OTHER_TXTS] WITH (NOLOCK) WHERE (([ITEM_ID] = %d) AND ([TXT_TYPE] = %s) AND ([FORMAT] = %d))
select	9337	0.0	0.0055	0.0001	0.6666	SELECT TOP (%d) [ID] FROM [AUTHORS] WITH (NOLOCK) WHERE (([SRC_UID] = %s) AND ([DATA_SRC_CODE] = %s))
update	9337	0.0007	0.1134	0.0103	109.9821	UPDATE [AUTHORS] SET [FIRST_NAMES] = %s, [LAST_NAME] = %s, [FULL_NAME] = %s, [NAME_SUFFIX] = %s, [IS_CORP] = %d, [BIOGRAPHICA
insert	9467	0.001	0.0959	0.002	35.6098	INSERT INTO [AUTHOR_PARTICIPATIONS] ([AUTHOR_ID], [AUTHOR_ROLE_CODE], [ITEM_ID], [AUTHOR_RANK], [DATA_SRC_CODE]) VALUES (%d,
select	10916	0.0	0.009	0.0001	0.8797	SELECT TOP (%d) [ID] FROM [PRICES] WITH (NOLOCK) WHERE (([ITEM_ID] = %d) AND ([PRICE_NOTE] = %s) AND ([MARKET_ASSIGNMENT_ID]
update	10916	0.0004	0.0368	0.0007	14.3729	UPDATE [PRICES] SET [EXCH_CODE] = %s, [PRICE] = %s, [BT_DISCOUNT_CODE] = %s WHERE ([ID] = %d)
update	11313	0.0004	0.0538	0.0008	16.2024	UPDATE [MARKET_ASSIGNMENTS] SET [MARKET_CODE] = %s, [ITEM_ID] = %d, [AVAIL_STATUS_ID] = %d, [ON_SALE_DATE] = NULL, [EXPECTED_
select	13712	0.0	0.0188	0.0001	1.079	SELECT TOP (%d) [ITEM_ID] FROM [ARCHIVED_ITEMS] WHERE (([ITEM_ID] = %d) AND ([STATUS] = %d))
select	13714	0.0	0.0131	0.0001	1.1517	SELECT TOP (%d) [ID] FROM [MARKET_ASSIGNMENTS] WITH (NOLOCK) WHERE (([MARKET_CODE] = %s) AND ([ITEM_ID] = %d) AND ([SUPPLIER_

The order of the fields is...
type of SQL statement
occurrences
minimum execution time
maximum execution time
mean time running the query
total time spent running the query
the query