p4clog.py #2

#!/usr/bin/python

# p4clog.py [ options ] < p4d-log-file > tables.csv
#
# $Id: //guest/perforce_software/log-analyzer/psla/p4clog.py#2 $
#
# -s - submit only
# -c - show locking by command
# -d - show delay analysis
# -h - show lock held histogram
# -i - interval for histogram instead of 600
# -w - show wait vs held analysis
# -v - log page I/Os, wait/hold more than 100ms, delays
#

import sys, re, time, getopt, math

# logParse - parse a line of p4d log tracking

class logParse:

	def __init__( p ):
		# what we're parsing:
		# 2013/01/17 22:01:11 pid 28322 u@c 10.0.50.39/10.0.0.40 [p4tter/v72 (brokered)] 'command args'
		# --- db.rev
		# ---   pages in+out+cached 222520+0+96
		# ---   locks read/write 1/0 rows get+pos+scan put+del 0+1+7372595 0+0
		# ---   total lock wait+held read/write 0ms+9578ms/0ms+0ms
		# --- db.change
		# ---   total lock wait+held read/write 0ms+9583ms/0ms+0ms
	
		p.pa = re.compile( "^\t(..../../.. ..:..:..) pid [^']*'([^ ']*)([^']*)" )
		p.pb = re.compile( "^--- (db.*)$" )
		p.pc = re.compile( "^---   pages in\+out\+cached ([^+]*)\+([^+]*)\+(.*)$" )
		p.pd = re.compile( "^---   locks .* put\+del ([^+]*)\+([^+]*)\+([^ ]*) ([^+]*)\+(.*)$" )
		p.pe = re.compile( "^---   total .* read/write ([^m]*)ms\+([^m]*)ms/([^m]*)ms\+([^m]*)ms$" )
		p.pf = re.compile( "^$" )

		p.reset()

	def reset( p ):

		p.date = p.command = p.args = p.table = ""

	# parse a single line of log

	def parse( p, line ):
		p.lineType = "none"
		ll = len( line )
	
		if( line[0] == "\n" ):
			p.lineType = "end"
			return
	
		if( ll > 5 and line[5] == "/" ):
			m = p.pa.search( line )
			if( m ): 
				p.date,p.command,p.args = m.group(1,2,3)
				p.lineType = "command"
			return
	
		if( ll > 4 and line[4] == "d" ):
			m = p.pb.search( line )
			if( m ): p.table = m.group(1)
			return
	
		if( ll > 6 and line[6] == "t" ):
			m = p.pe.search( line )
			if( m ): 
				p.lrw,p.lrh,p.lww,p.lwh = map(int,m.group(1,2,3,4))
				p.lineType = "locks"
			return
	
		if( ll > 6 and line[6] == "p" ):
			m = p.pc.search( line )
			if( m ): 
				p.pgi,p.pgo,p.pgc = map(int,m.group(1,2,3))
				p.lineType = "pages"
				p.isPages = True
			return
	
		return
	
		# don't use these yet
	
		if( ll > 6 and line[6] == "l" ):
			m = p.pd.search( line )
			if( m ): rgt,rpo,rsc,rpt,rdl = map(int,m.group(1,2,3,4,5))
			return

# tableCounts - read/write wait/held time counter

class tableCounts:

	def __init__( s, lrw, lrh, lww, lwh ):
		s.readWaitCount = lrw > 0; s.readWaitTime = lrw
		s.readHeldCount = lrh > 0; s.readHeldTime = lrh
		s.writeWaitCount = lww > 0; s.writeWaitTime = lww
		s.writeHeldCount = lwh > 0; s.writeHeldTime = lwh

	def __iadd__( s, o ):
	
		s.readHeldCount += o.readHeldCount
		s.readHeldTime += o.readHeldTime
		s.readWaitCount += o.readWaitCount
		s.readWaitTime += o.readWaitTime
	
		s.writeHeldCount += o.writeHeldCount
		s.writeHeldTime += o.writeHeldTime
		s.writeWaitCount += o.writeWaitCount
		s.writeWaitTime += o.writeWaitTime
	
		return s

	def __ior__( s, o ):

		# add waits, but max of held
	
		s.readWaitTime += o.readWaitTime
		s.writeWaitTime += o.writeWaitTime
	
		if( o.readHeldTime > s.readHeldTime ):
			s.readHeldTime = o.readHeldTime
		if( o.writeHeldTime > s.writeHeldTime ):
			s.writeHeldTime = o.writeHeldTime
	
		return s

# Spanner - track how long locks are held for one db file

class Spanner:

	# per interval result

	class Result:

		def __init__( r, time, secsHeld, secsFree, longestHeld ):
			r.time = time
			r.secsHeld = secsHeld
			r.secsFree = secsFree
			r.longestHeld = longestHeld

	# when the log file begins

	epoch = 0

	def __init__( s ):

		# number of locks held in each second 
		# since log file begins (gets long!)
	
		s.byTheSeconds = []
		s.byTheInterval = []

	# translate log file date into seconds since epoch

	def secs( s, date ):

		try:
			t = int( time.mktime( time.strptime( date, "%Y/%m/%d %H:%M:%S" ) ) )
			if( Spanner.epoch == 0 ): Spanner.epoch = t
			return t - Spanner.epoch
	
		except ValueError:
			print ("bad date %s" % date, file=sys.stderr)
			return 0

	# process a single lock hold

	def span( s, start, held ):

		# translate start/held to start/end in second since epoch
	
		heldStart = s.secs( start )
		heldEnd = int(heldStart + ( held + 500 ) / 1000)
	
		# sometime the log file is out of order
	
		if( heldStart < 0 or heldStart == heldEnd ):
			return
	
		# dynamically extend array
	
		if( len( s.byTheSeconds ) <= heldEnd ):
			s.byTheSeconds.extend( [ 0 ] * ( heldEnd + 1 - len( s.byTheSeconds ) ) )
	
		# count this as an instance this lock was held this second
	
		for x in range( heldStart, heldEnd ):
			s.byTheSeconds[ x ] += 1

	# condense into intervals

	def condense( s, interval ):

		lastFree = -1
		longestHeld = 0
	
		# for each 'interval' seconds
		# find the time held/free/longest
		# and dump out a single line
	
		for x in range( 0, len( s.byTheSeconds ), interval ):
	
			secsHeld = 0
			secsFree = interval
	
			for y in range( x, min( x + interval, len( s.byTheSeconds ) ) ):
	
				sex = s.byTheSeconds[ y ]
		
				secsHeld += sex
				secsFree -= sex == 0
		
				if( sex == 0 ):
					lastFree = y
				elif( y - lastFree > longestHeld ):
					longestHeld = y - lastFree
	
			s.byTheInterval.append( s.Result( Spanner.epoch + x, secsHeld, secsFree, longestHeld ) )
	
			longestHeld = 0

	# dump one table's locks

	def dump( s, t, interval ):

		s.condense( interval )
	
		if( len( s.byTheInterval ) == 0 ): return
	
		print(">>> %s saturation each %d seconds" % ( t, interval ))
		print("%s,%s,%s,%s" % ( "time", "not free", "held", "longest held" ))
	
		# for each 'interval' seconds
		# find the time held/free/longest
		# and dump out a single line
	
		for x in s.byTheInterval:
	
			print("%s,%d,%d,%d" % ( 
				time.ctime( x.time ),
				x.secsFree,
				x.secsHeld,
				x.longestHeld ))

# LocksByTime: one spanner for each table

class LocksByTime:

	def __init__( s ):

		s.tableSpanner = {}

	def tally( s, commandTables, date ):

		for t in commandTables:
	
			if( not t in s.tableSpanner ):
				s.tableSpanner[ t ] = Spanner()
	
			s.tableSpanner[ t ].span( date,
				commandTables[ t ].writeHeldTime +
				commandTables[ t ].readHeldTime )

	def dump( s, spannerInterval ):

		for t in s.tableSpanner:
			s.tableSpanner[ t ].dump( t, spannerInterval )

#
# WaitVsHeld -- calculate how long locks are held waiting for others
#
#	.tally() - given lock+held times for all tables used by a command's
#		processing, calculate which tables are holding up others
#
#	.dump() - dump out all wait vs held times for tables held more than
#		1 seconds total
#

class WaitVsHeld:

	def __init__( s ):

		s.table = {}

	def tally( s, commandTables, showWaitVsHeld, count, command ):

		for t in commandTables:
	
			# wait vs held
	
			held = commandTables[ t ].writeHeldTime
	
			if( held == 0 ): continue
	
			for t2 in commandTables:
	
				wait = commandTables[ t2 ].writeWaitTime
		
				if( t == t2 or wait > held or wait <= held / 2 ):
					continue
		
				if( not t in s.table ):
					s.table[ t ] = {}
				if( not t2 in s.table[ t ] ):
					s.table[ t ][ t2 ] = tableCounts( 0, 0, 0, 0 )
		
				s.table[ t ][ t2 ] += commandTables[ t2 ]
		
				# for interest sake
		
				if( showWaitVsHeld ):
					print(count, "held", t, held, "wait", t2, wait, command)

	def dump( s, totalTables ):

		print(">>> Wait times causing hold times")

		print("%s,%s,%s,%s,%s,%s" % (
			"table", 
			"write-wait-Time", 
			"read-wait-Time", 
			"table",
			"write-held-Time",
			"read-held-Time" ))

		for t in s.table:
			tc = totalTables[ t ]
			for t2 in s.table[ t ]:
				tg = s.table[ t ][ t2 ]
		
				if( tg.writeWaitTime > 1000 and tc.writeHeldTime > 1000 or
					tg.readWaitTime > 1000 and tc.readHeldTime > 1000 ):
					print("%s,%d,%d,%s,%d,%d" % (
						t2, 
						tg.writeWaitTime / 1000,
						tg.readWaitTime / 1000,
						t, 
						tc.writeHeldTime / 1000,
						tc.readHeldTime / 1000 ))

# 
# TimesByCommand -- calculate read+write hold time for each command
#
#	.tally() - add a single read+write hold to a command's total
#	.dump() - dump out each command's total
#

class TimesByCommand:

	def __init__( s ):

		s.byCommand = {}

	def tally( s, table, command, tc ):

		# by table then command 
	
		if( not table in s.byCommand ):
			s.byCommand[ table ] = {}
		if( not command in s.byCommand[ table ] ):
			s.byCommand[ table ][ command ] = tableCounts( 0, 0, 0, 0 )
	
		s.byCommand[ table ][ command ] += tc

	def dump( s ):

		print(">>> Table hold times by command")
		print("%s,%s,%s,%s" % (
			"table", 
			"command",
			"read-held-Time", 
			"write-held-Time" ))
	
		for t in s.byCommand:
			for c in s.byCommand[ t ]:
				tt = s.byCommand[ t ][ c ]
				if( tt.readHeldTime >= 1000 or tt.writeHeldTime >= 1000 ):
					print("%s,%s,%d,%d" % (
						t, c, 
						tt.readHeldTime/1000,
						tt.writeHeldTime/1000 ))

#
# TimesByTable -- calculate read+write/wait+hold time for each table
#
#	.tally() - add a single read+write/wait+hold to a table's total
#	.dump() - dump out each table's tally, using a grandTotal for %age
#

class TimesByTable:

	def __init__( s ):

		s.byTable = {}

	def tally( s, table, tc ):

		if( not table in s.byTable ):
			s.byTable[ table ] = tableCounts( 0, 0, 0, 0 )

		s.byTable[ table ] += tc

	def dump( s, grandTotal ):

		grandTotal += tableCounts( 1, 1, 1, 1 ) # no divide by zero errors
	
		print(">>> Hold and wait times per table")
	
		print("%s,%s,%s,%s,%s,%s,%s" % (
			"table", 
			"read-wait-Time", 
			"%-of-Total",
			"read-held-Time", 
			"write-wait-Time", 
			"%-of-Total",
			"write-held-Time" ))
	
		# sort descending by readWaitTime
	
		#for t,tc in s.byTable.items():
		for t,tc in sorted( s.byTable.items(), key=lambda v: 0-(v[1].readWaitTime + v[1].writeWaitTime) ):
	
			print("%s,%d,%d%%,%d,%d,%d%%,%d" % (
				t, 
				tc.readWaitTime/1000, 
				tc.readWaitTime * 100 / grandTotal.readWaitTime,
				tc.readHeldTime/1000,
				tc.writeWaitTime/1000,
				tc.writeWaitTime * 100 / grandTotal.writeWaitTime,
				tc.writeHeldTime/1000 ))

#
# WaitDelays - how much commands are delayed by wait times
#

class WaitDelays:

	def __init__( s ):

		s.maxSlots = 10
		s.power = 2
		s.delaySlots = [ 0 ] * s.maxSlots

	def tally( s, commandTotal, logDelays, count, command ):

		wait = commandTotal.readWaitTime + commandTotal.writeWaitTime 
		held = commandTotal.readHeldTime + commandTotal.writeHeldTime
	
		if( wait < 1000 or wait < held / 10 ):
			return
	
		if( logDelays ):
			print(count, "commandWait", wait, "commandHeld", held, command)
	
		slot = int( math.log( wait / 1000, s.power ) )
	
		if( slot >= s.maxSlots ):
			slot = s.maxSlots-1
	
		s.delaySlots[ slot ] += 1

	def dump( s ):

		print(">>> Commands delayed")
		print("%s,%s" % ( "Seconds of delay", "Commands affected" ))
	
		for x in range( 0, s.maxSlots ):
			print("%d,%d" % ( s.power**x, s.delaySlots[ x ] ))

def main():

	# process args

	showByCommand = False
	showDelays = False
	showWaitVsHeld = False
	showHisto = False
	showTally = False
	spannerInterval = 600
	submitOnly = False
	verboseLogging = False

	try:
		opts, args = getopt.getopt( sys.argv[1:], "acdhi:stwv" )

	except getopt.error as msg:
		print(msg)
		print("Usage: p4clog.py [ -v ] [ -acdhswt ] [ -i interval ] < log-file")
		sys.exit(2)

	for o, a in opts:
		if o == '-h': showHisto = True
		elif o == '-s': submitOnly = True
		elif o == '-i': spannerInterval = int(a)
		elif o == '-c': showByCommand = True
		elif o == '-d': showDelays = True
		elif o == '-t': showTally = True
		elif o == '-a': showHisto = showByCommand = showDelays = showTally = showWaitVsHeld = True
		elif o == '-w': showWaitVsHeld = True
		elif o == '-v': verboseLogging = True

	# per table counts of held and wait times

	lineCount = 0
	commandCount = 0
	pagesIn = 0
	pagesOut = 0
	firstDate = 0
	lastDate = 0

	p = logParse()

	commandTables = {}

	timesByTable = TimesByTable()
	timesByCommand = TimesByCommand()
	waitVsHeld = WaitVsHeld()
	locksByTime = LocksByTime()
	waitDelays = WaitDelays()

	commandTotal = tableCounts( 0, 0, 0, 0 )
	grandTotal = tableCounts( 0, 0, 0, 0 )

	for line in sys.stdin:

		lineCount += 1

		if( lineCount % 1000000 == 0 ):
			print("%s" % lineCount, file=sys.stderr)

		# match one of the lines

		p.parse( line )

		# per table tallying

		if( submitOnly and p.command != "dm-CommitSubmit" ):
			continue

		# command count

		if( p.lineType == "command" ):
			commandCount += 1
			if( firstDate == 0 ): firstDate = p.date
			lastDate = p.date

		# pages

		if( p.lineType == "pages" ):

			pagesIn += p.pgi
			pagesOut += p.pgo

			if( verboseLogging ):
				if( p.pgi + p.pgo > 0 ):
					print(lineCount, "pages", p.table, p.pgi + p.pgo, p.command, p.args)

			continue

		# locks

		if( p.lineType == "locks"  ):

			# for interest sake

			if( verboseLogging ):
				if( p.lrh > 100 ): print(lineCount, "readheld", p.table, p.lrh, p.command, p.args )
				if( p.lwh > 100 ): print(lineCount, "writeheld", p.table, p.lwh, p.command, p.args )
				if( p.lrw > 100 ): print(lineCount, "readwait", p.table, p.lrw, p.command, p.args )
				if( p.lww > 100 ): print(lineCount, "writewait", p.table, p.lww, p.command, p.args)

			# remember count for this table for this command
			# and add it to the grand total

			tc = tableCounts( p.lrw, p.lrh, p.lww, p.lwh )
			commandTables[ p.table ] = tc
			commandTotal |= tc
			grandTotal += tc

			# tally by table and by command name

			timesByTable.tally( p.table, tc )
			timesByCommand.tally( p.table, p.command, tc )

		# per command tallying

		if( p.lineType == "end" ):

			if( showHisto ):
				locksByTime.tally( commandTables, p.date )

			if( showWaitVsHeld ):
				waitVsHeld.tally( commandTables, verboseLogging, lineCount, p.command )

			if( showDelays ):
				waitDelays.tally( commandTotal, verboseLogging, lineCount, p.command )

			commandTotal = tableCounts( 0, 0, 0, 0 )
			commandTables = {}

			p.reset()

	# Dump it all out

	if( showTally ):
		print(">>> Log file summary")
		print("Lines,Commands,Pages Read,Pages Written,First Date,Last Date")
		print("%d,%d,%d,%d,%s,%s" % ( lineCount, commandCount, pagesIn, pagesOut, firstDate, lastDate ))

	if( showDelays ):
		waitDelays.dump()

	timesByTable.dump( grandTotal )

	if( showWaitVsHeld ):
		waitVsHeld.dump( timesByTable.byTable )

	if( showByCommand ):
		timesByCommand.dump()

	if( showHisto ):
		locksByTime.dump( spannerInterval )

main()