#!/usr/bin/ruby ############################################################################## # # Copyright (c) 2008,2011 Perforce Software, Inc. All rights reserved. # # Redistribution and use in source and binary forms, with or without # modification, are permitted provided that the following conditions are met: # # 1. Redistributions of source code must retain the above copyright # notice, this list of conditions and the following disclaimer. # # 2. Redistributions in binary form must reproduce the above copyright # notice, this list of conditions and the following disclaimer in the # documentation and/or other materials provided with the distribution. # # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" # AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE # IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE # ARE DISCLAIMED. IN NO EVENT SHALL PERFORCE SOFTWARE, INC. BE LIABLE FOR ANY # DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES # (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; # LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND # ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF # THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. # # = Date # # $Date: 2021/01/22 $ # # = Description # # Output SQL queries generated by parsing commands logged in a Perforce # server log file. # The output can be imported directly in any SQL database. # # log2sql populates the following tables: # # +----------------+----------+------+-----+ # | process | # +----------------+----------+------+-----+ # | Field | Type | Null | Key | # +----------------+----------+------+-----+ # | processKey | char(32) | NO | PRI | # | lineNumber | int | NO | PRI | # | startTime | date | NO | | # | endTime | date | YES | | # | computedLapse | float | YES | | # | completedLapse | float | YES | | # | pid | int | NO | | # | user | text | NO | | # | workspace | text | NO | | # | ip | text | NO | | # | app | text | NO | | # | cmd | text | NO | | # | args | text | YES | | # | uCpu | int | YES | | # | sCpu | int | YES | | # | diskIn | int | YES | | # | diskOut | int | YES | | # | ipcIn | int | YES | | # | ipcOut | int | YES | | # | maxRss | int | YES | | # | pageFaults | int | YES | | # | rpcMsgsIn | int | YES | | # | rpcMsgsOut | int | YES | | # | rpcSizeIn | int | YES | | # | rpcSizeOut | int | YES | | # | rpcHimarkFwd | int | YES | | # | rpcHimarkRev | int | YES | | # | running | int | NO | | # | error | text | YES | | # +----------------+----------+------+-----+ # # +----------------+--------------+------+-----+ # | tableUse | # +----------------+--------------+------+-----+ # | Field | Type | Null | Key | # +----------------+--------------+------+-----+ # | processKey | char(32) | NO | PRI | # | lineNumber | int | NO | PRI | # | tableName | varchar(255) | NO | PRI | # | pagesIn | int | YES | | # | pagesOut | int | YES | | # | pagesCached | int | YES | | # | readLocks | int | YES | | # | writeLocks | int | YES | | # | getRows | int | YES | | # | posRows | int | YES | | # | scanRows | int | YES | | # | putRows | int | YES | | # | delRows | int | YES | | # | totalReadWait | int | YES | | # | totalReadHeld | int | YES | | # | totalWriteWait | int | YES | | # | totalWriteHeld | int | YES | | # | maxReadWait | int | YES | | # | maxReadHeld | int | YES | | # | maxWriteWait | int | YES | | # | maxWriteHeld | int | YES | | # +----------------+--------------+------+-----+ # # = Usage # # log2sql.rb -d log_file # # = Requirements # # Ruby: http://www.ruby-lang.org # ############################################################################## require "getoptlong" require "time" require "digest/md5" class Command attr_accessor :processKey,:pid,:startTime,:endTime,:computedLapse, :completedLapse,:user,:workspace,:ip,:app,:name,:args,:uCpu, :sCpu,:diskIn,:diskOut,:ipcIn,:ipcOut,:maxRss, :pageFaults,:rpcMsgsIn,:rpcMsgsOut,:rpcSizeIn,:rpcSizeOut, :rpcHimarkFwd,:rpcHimarkRev,:running,:lineNumber,:error def initialize(processKey,lineNumber,pid,startTime, user,workspace,ip,app,name,args) @processKey = processKey @lineNumber = lineNumber @pid = pid @startTime = startTime @user = escapeChar(user) @workspace = escapeChar(workspace) @ip = ip @app = app @name = name if args @args = escapeChar(args) else @args = "NULL" end @endTime = @computedLapse = @completedLapse = @uCpu = "NULL" @sCpu = @diskIn = @diskOut = @ipcIn = @ipcOut = @maxRss = "NULL" @pageFaults = @rpcMsgsIn = @rpcMsgsOut = @rpcSizeOut = "NULL" @rpcSizeIn = @rpcHimarkFwd = @rpcHimarkRev = @error = "NULL" @running = 0 end def escapeChar(str) str = str.gsub("\\"){"\\\\"} str = str.gsub("\""){"\\\""} return str end def setUsage(uCpu,sCpu,diskIn,diskOut,ipcIn,ipcOut,maxRss,pageFaults) @uCpu = uCpu @sCpu = sCpu @diskIn = diskIn @diskOut = diskOut @ipcIn = ipcIn @ipcOut = ipcOut @maxRss = maxRss @pageFaults = pageFaults end def setRpc(rpcMsgsIn,rpcMsgsOut,rpcSizeIn, rpcSizeOut,rpcHimarkFwd,rpcHimarkRev) @rpcMsgsIn = rpcMsgsIn @rpcMsgsOut = rpcMsgsOut @rpcSizeIn = rpcSizeIn @rpcSizeOut = rpcSizeOut @rpcHimarkFwd = rpcHimarkFwd @rpcHimarkRev = rpcHimarkRev end end class Table attr_accessor :processKey,:lineNumber,:tableName, :pagesIn,:pagesOut,:pagesCached,:readLocks, :writeLocks,:getRows,:posRows,:scanRows,:putRows,:delRow, :totalReadWait,:totalReadHeld, :totalWriteWait,:totalWriteHeld, :maxReadWait,:maxReadHeld, :maxWriteWait,:maxWriteHeld def initialize(processKey,lineNumber,tableName) @processKey = processKey @lineNumber = lineNumber @tableName = tableName @pagesIn = @pagesOut = @pagesCached = "NULL" @readLocks = @writeLocks = @getRows = @posRows = @scanRows = "NULL" @putRows = @delRow = @totalReadWait = @totalReadHeld = "NULL" @totalWriteWait = @totalWriteHeld = @maxReadWait = "NULL" @maxReadHeld = @maxWriteWait = @maxWriteHeld = "NULL" end def setPages(pagesIn,pagesOut,pagesCached) @pagesIn = pagesIn @pagesOut = pagesOut @pagesCached = pagesCached end def setLocksRows(readLocks,writeLocks,getRows,posRows, scanRows,putRows,delRow) @readLocks = readLocks @writeLocks = writeLocks @getRows = getRows @posRows = posRows @scanRows = scanRows @putRows = putRows @delRow = delRow end def setTotalLock(totalReadWait,totalReadHeld, totalWriteWait,totalWriteHeld) @totalReadWait = totalReadWait @totalReadHeld = totalReadHeld @totalWriteWait = totalWriteWait @totalWriteHeld = totalWriteHeld end def setMaxLock(maxReadWait,maxReadHeld,maxWriteWait,maxWriteHeld) @maxReadWait = maxReadWait @maxReadHeld = maxReadHeld @maxWriteWait = maxWriteWait @maxWriteHeld = maxWriteHeld end end class FifoList attr_accessor :max,:list def initialize(max) @list = Array.new @max = max end def add(cmd) if list.length + 1 > max list.delete_at(1) end list.push(cmd) end def remove(cmd) list.each_index do |i| if (list[i].processKey == cmd.processKey) list.delete_at(i) break end end end def getLineNumber(cmd) lineNumber = 0 list.each do |p| if (p.processKey == cmd.processKey) lineNumber = p.lineNumber break end end lineNumber end end class Log2sql attr_reader :logname,:dbname,:logfile,:ckpSize, :readBytes,:mod,:cmds,:lastCompletedCmds def initialize(logname, dbname) @logname = logname @dbname = dbname @ckpSize = File.size(logname) @logfile = File.open(logname,"r") @cmds = Hash.new @lastCompletedCmds = FifoList.new(1000) @readBytes = 0.0 @mod = 10.0 @running = 0 db_create_database() db_create_process() db_create_tableUse() db_commit(FALSE) printf($stderr,"Processing %s: 0%%", logname) $stderr.flush end def terminate() flush_output() db_commit(TRUE) end def readLogfile() line = logfile.gets() if line if line.respond_to?(:encode) line = line.encode("utf-8", 'binary', :invalid => :replace, :undef => :replace) end @readBytes += line.length if (((readBytes / ckpSize) * 100.0) / mod).floor == 1.0 printf($stderr,"...%d%%", mod) $stderr.flush @mod += 10 end end line end def getLineNumber() logfile.lineno end def db_commit(state) if (state) query = "COMMIT;" else query = "SET autocommit=0;" end puts(query) end def db_create_database() query = "CREATE DATABASE IF NOT EXISTS " + dbname + ";" puts(query) query = "USE " + dbname + ";" puts(query) end def db_create_process() query = "DROP TABLE IF EXISTS process;" puts(query) query = "CREATE TABLE process (processkey CHAR(32) NOT NULL, lineNumber INT NOT NULL, pid INT NOT NULL, startTime DATETIME NOT NULL,endTime DATETIME NULL, computedLapse FLOAT NULL,completedLapse FLOAT NULL, user TEXT NOT NULL, workspace TEXT NOT NULL, ip TEXT NOT NULL, app TEXT NOT NULL, cmd TEXT NOT NULL, args TEXT NULL, uCpu INT NULL, sCpu INT NULL, diskIn INT NULL, diskOut INT NULL, ipcIn INT NULL, ipcOut INT NULL, maxRss INT NULL, pageFaults INT NULL, rpcMsgsIn INT NULL, rpcMsgsOut INT NULL, rpcSizeIn INT NULL, rpcSizeOut INT NULL, rpcHimarkFwd INT NULL, rpcHimarkRev INT NULL, running INT NULL, error TEXT NULL, PRIMARY KEY (processkey, lineNumber));" puts(query) end def db_create_tableUse() query = "DROP TABLE IF EXISTS tableUse;" puts(query) query = "CREATE TABLE tableUse (processkey CHAR(32) NOT NULL, lineNumber INT NOT NULL, tableName VARCHAR(255) NOT NULL, pagesIn INT NULL, pagesOut INT NULL, pagesCached INT NULL, readLocks INT NULL, writeLocks INT NULL, getRows INT NULL, posRows INT NULL, scanRows INT NULL, putRows int NULL, delRows INT NULL, totalReadWait INT NULL, totalReadHeld INT NULL, totalWriteWait INT NULL, totalWriteHeld INT NULL, maxReadWait INT NULL, maxReadHeld INT NULL, maxWriteWait INT NULL, maxWriteHeld INT NULL, PRIMARY KEY (processkey, lineNumber, tableName));" puts(query) end def addCommand(cmd, vtrack) cmd.running = @running cmds[cmd.pid] = cmd if !vtrack @running = @running + 1 end end def deleteCommand(cmd, vtrack) if cmds.has_key?(cmd.pid) sql_process_insert(cmds[cmd.pid]) cmds.delete(cmd.pid) if !vtrack @running = @running - 1 end end end def computed(pid,computedLapse) if cmds.has_key?(pid) # sum all the compute values of a same command sum = cmds[pid].computedLapse.to_f sum += computedLapse.to_f cmds[pid].computedLapse = sum.to_s end end def completed(pid,endTime,completedLapse) if cmds.has_key?(pid) cmds[pid].endTime = endTime cmds[pid].completedLapse = completedLapse.to_f.to_s lastCompletedCmds.add(cmds[pid]) deleteCommand(cmds[pid], FALSE) end end def track(cmd,line) tables = Hash.new tableName = nil rpcMsgsIn = rpcMsgsOut = rpcSizeIn = rpcSizeOut = 0 rpcHimarkFwd = rpcHimarRev =uCpu = 0 sCpu = diskIn = diskOut = ipcIn = ipcOut = maxRss = pageFaults = 0 readLocks = writeLocks = getRows = posRows = scanRows = 0 putRows = delRow = totalReadWait = totalReadHeld = 0 totalWriteWait = totalWriteHeld = maxReadWait = 0 maxReadHeld = maxWriteWait = maxWriteHeld = 0 lineNumber = lastCompletedCmds.getLineNumber(cmd) if lineNumber > 0 cmd.lineNumber = lineNumber lastCompletedCmds.remove(cmd) else addCommand(cmd, TRUE) end while line && RE_TRACK.match(line) if match = RE_TRACK_LAPSE.match(line) cmd.completedLapse = match[1] elsif (match = RE_FAILED_AUTH.match(line)) || (match = RE_KILLED_BY.match(line)) || (match = RE_EXITED.match(line)) cmd.error = "\"" + match[1] + "\"" elsif match = RE_TRACK_USAGE.match(line) cmd.setUsage(match[1],match[2],match[3],match[4], match[5],match[6],match[7],match[8]) elsif match = RE_TRACK_RPC.match(line) cmd.setRpc(match[1],match[2],match[3], match[4],match[5],match[6]) elsif match = RE_TRACK_TABLE.match(line) tableName = match[1] tables[tableName] = Table.new(cmd.processKey, cmd.lineNumber,tableName) elsif match = RE_TRACK_PAGES.match(line) if tables.has_key?(tableName) tables[tableName].setPages(match[1],match[2],match[3]) end elsif match = RE_TRACK_LOCKS_ROWS.match(line) if tables.has_key?(tableName) tables[tableName].setLocksRows(match[1],match[2], match[3],match[4], match[5],match[6], match[7]) end elsif match = RE_TRACK_TOTAL_LOCK.match(line) if tables.has_key?(tableName) tables[tableName].setTotalLock(match[1],match[2], match[3],match[4]) # The max is only reported if there is more than one # lock taken on the table if (tables[tableName].readLocks.to_i < 2 && tables[tableName].writeLocks.to_i < 2) tables[tableName].setMaxLock(match[1],match[2], match[3],match[4]) end end elsif match = RE_TRACK_MAX_LOCK.match(line) if tables.has_key?(tableName) tables[tableName].setMaxLock(match[1],match[2], match[3],match[4]) end end line = readLogfile() end deleteCommand(cmd, TRUE) sql_process_update(cmd) tables.values.each do |table| sql_tableUse_insert(table) end end def flush_output() cmds.values.each do |p| sql_process_insert(p) end $stderr.puts("") end def sql_process_insert(cmd) query = sprintf("INSERT IGNORE INTO process VALUES (\"%s\",%d,%d,%s,%s,%s,%s,\"%s\",\"%s\",\"%s\",\"%s\",\"%s\",\"%s\",%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%d,%s);", cmd.processKey,cmd.lineNumber,cmd.pid, cmd.startTime,cmd.endTime,cmd.computedLapse, cmd.completedLapse,cmd.user,cmd.workspace, cmd.ip,cmd.app,cmd.name,cmd.args,cmd.rpcMsgsIn, cmd.rpcMsgsOut,cmd.rpcSizeIn,cmd.rpcSizeOut, cmd.rpcHimarkFwd,cmd.rpcHimarkRev,cmd.uCpu, cmd.sCpu,cmd.diskIn,cmd.diskOut,cmd.ipcIn,cmd.ipcOut, cmd.maxRss,cmd.pageFaults,cmd.running,cmd.error) puts(query) end def sql_process_update(cmd) query = sprintf("UPDATE process SET uCpu=%s,sCpu=%s,diskIn=%s,diskOut=%s,ipcIn=%s,ipcOut=%s,maxRss=%s,pageFaults=%s,rpcMsgsIn=%s,rpcMsgsOut=%s,rpcSizeIn=%s,rpcSizeOut=%s,rpcHimarkFwd=%s,rpcHimarkRev=%s,error=%s WHERE processKey = \"%s\" and lineNumber = %d;", cmd.uCpu,cmd.sCpu,cmd.diskIn,cmd.diskOut,cmd.ipcIn, cmd.ipcOut,cmd.maxRss,cmd.pageFaults,cmd.rpcMsgsIn, cmd.rpcMsgsOut,cmd.rpcSizeIn,cmd.rpcSizeOut, cmd.rpcHimarkFwd,cmd.rpcHimarkRev,cmd.error, cmd.processKey,cmd.lineNumber) puts(query) if (cmd.completedLapse != "NULL") query = sprintf("UPDATE process SET endTime=DATE_ADD(startTime,INTERVAL %d SECOND) WHERE processKey = \"%s\" and lineNumber = %d and endTime IS NULL;", cmd.completedLapse,cmd.processKey,cmd.lineNumber) else query = sprintf("UPDATE process SET endTime=startTime WHERE processKey = \"%s\" and lineNumber = %d and endTime IS NULL;", cmd.processKey,cmd.lineNumber) end puts(query) end def sql_tableUse_insert(tab) query = sprintf("INSERT IGNORE INTO tableUse VALUES (\"%s\",%d,\"%s\",%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s);", tab.processKey,tab.lineNumber,tab.tableName,tab.pagesIn, tab.pagesOut,tab.pagesCached,tab.readLocks, tab.writeLocks,tab.getRows,tab.posRows,tab.scanRows, tab.putRows,tab.delRow, tab.totalReadWait,tab.totalReadHeld, tab.totalWriteWait,tab.totalWriteHeld, tab.maxReadWait,tab.maxReadHeld, tab.maxWriteWait,tab.maxWriteHeld) puts(query) end end def croakusage puts("Usage: log2sql.rb -d log_filename" ) exit(0) end ###################### # START OF MAIN SCRIPT ###################### RE_CMD = Regexp.new( '^\t(\d+/\d+/\d+ \d+:\d+:\d+) pid (\d+) (.*)@(.*) (.*) \[(.*)\] \'(\w+-\w+) (.*)\'.*' ) RE_CMD_NOARG = Regexp.new( '^\t(\d+/\d+/\d+ \d+:\d+:\d+) pid (\d+) (.*)@(.*) (.*) \[(.*)\] \'(\w+-\w+)\'.*' ) RE_COMPUTE = Regexp.new( '^\t(\d+/\d+/\d+ \d+:\d+:\d+) pid (\d+) compute end ([0-9]+|[0-9]+\.[0-9]+|\.[0-9]+)s .*' ) RE_COMPLETED = Regexp.new( '^\t(\d+/\d+/\d+ \d+:\d+:\d+) pid (\d+) completed ([0-9]+|[0-9]+\.[0-9]+|\.[0-9]+)s .*') RE_TRACK = Regexp.new( '^---|^locks acquired by blocking after 3 non-blocking attempts') RE_TRACK_LAPSE = Regexp.new( '^--- lapse (\d+)') RE_TRACK_RPC = Regexp.new( '^--- rpc msgs/size in\+out (\d+)\+(\d+)/(\d+)mb\+(\d+)mb himarks (\d+)/(\d+)') RE_TRACK_USAGE = Regexp.new( '^--- usage (\d+)\+(\d+)us (\d+)\+(\d+)io (\d+)\+(\d+)net (\d+)k (\d+)pf') RE_FAILED_AUTH = Regexp.new('^--- (failed authentication check)') RE_KILLED_BY = Regexp.new('^--- (killed by .*)') RE_EXITED = Regexp.new('^--- (exited on fatal server error)') RE_TRACK_TABLE = Regexp.new('^--- db.([a-zA-Z]*)') RE_TRACK_PAGES = Regexp.new( '^--- pages in\+out\+cached (\d+)\+(\d+)\+(\d+)') RE_TRACK_LOCKS_ROWS = Regexp.new('^--- locks read/write (\d+)/(\d+) rows get\+pos\+scan put\+del (\d+)\+(\d+)\+(\d+) (\d+)\+(\d+)') RE_TRACK_TOTAL_LOCK = Regexp.new('^--- total lock wait\+held read/write (\d+)ms\+(\d+)ms/(\d+)ms\+(\d+)ms') RE_TRACK_MAX_LOCK = Regexp.new('^--- max lock wait\+held read/write (\d+)ms\+(\d+)ms/(\d+)ms\+(\d+)ms|--- locks wait+held read/write (\d+)ms\+(\d+)ms/(\d+)ms\+(\d+)ms') opts = GetoptLong.new(["--dbname", "-d", GetoptLong::REQUIRED_ARGUMENT], ["--help", "-h", GetoptLong::NO_ARGUMENT]) dbname = nil opts.each do |opt,arg| if opt == "--dbname" || opt == "-d" dbname = arg elsif opt == "--help" || opt == "-h" croakusage end end logname = $<.filename if !logname || !dbname croakusage end log2sql = Log2sql.new(logname,dbname) line = log2sql.readLogfile() while line nextLine = nil # # Pattern matching a command # if (match = RE_CMD.match(line)) || (match = RE_CMD_NOARG.match(line)) pid = match[2] date = Date._parse(match[1]) startTime = Time.local(date[:year],date[:mon],date[:mday], date[:hour],date[:min], date[:sec]).strftime("\"%Y-%m-%d %H:%M:%S\"") user = match[3] workspace = match[4] ip = match[5] # following gsub required due to a 2009.2 P4V bug app = match[6].gsub("\x00"){"/"} name = match[7] args = match[8] processKey = Digest::MD5.new << line cmd = Command.new(processKey,log2sql.getLineNumber(),pid,startTime, user,workspace,ip,app,name,args) nextLine = log2sql.readLogfile() if nextLine && RE_TRACK.match(nextLine) log2sql.track(cmd,nextLine) else log2sql.addCommand(cmd, FALSE) end # # Pattern matching a compute line # elsif match = RE_COMPUTE.match(line) pid = match[2] computedLapse = match[3] log2sql.computed(pid,computedLapse) # # Pattern matching a completed line # elsif match = RE_COMPLETED.match(line) pid = match[2] date = Date._parse(match[1]) endTime = Time.local(date[:year],date[:mon],date[:mday], date[:hour],date[:min], date[:sec]).strftime("\"%Y-%m-%d %H:%M:%S\"") completedLapse = match[3] log2sql.completed(pid,endTime,completedLapse) end if nextLine line = nextLine else line = log2sql.readLogfile() end end log2sql.terminate()