p4clog.py #1

#!/usr/bin/python

#
#
# Copyright (c) 2013, 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.
# 
#


# p4clog.py [ options ] < p4d-log-file > tables.csv
#
# -s - submit only
# -h - do the per table histogram
# -i - interval for histogram instead of 600
# -l - log all commands that wait/hold more than 100ms
# -w - show wait vs held logging
# -v - -hlw
#

import sys, re, time, getopt

# 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)
	    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

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

class Spanner:

    # 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 = []

    # 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 >> sys.stderr, "bad date %s\n" % date,
	    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 = 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

    # dump one table's locks

    def dump( s, t, interval ):

	print "%s,%s,%s,%s,%s\n" % ( "table", "time", "held", "not free", "longest held" ),

	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 * interval, interval ):

	    secsHeld = 0
	    secsFree = interval

	    for y in range( x, x + interval ):
		sex = s.byTheSeconds[ y ]

		secsHeld += sex
		secsFree -= sex == 0

		if( sex == 0 ):
		    lastFree = y
		elif( y - lastFree > longestHeld ):
		    longestHeld = y - lastFree

	    print "%s,%s,%d,%d,%d\n" % ( 
	    	t, 
		time.ctime( Spanner.epoch + x ),
		secsHeld,
		secsFree,
		longestHeld ),

	    longestHeld = 0

# 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 )

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 "%s,%s,%s,%s,%s,%s\n" % (
        	"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\n" % (
			    t2, 
			    tg.writeWaitTime / 1000,
			    tg.readWaitTime / 1000,
			    t, 
			    tc.writeHeldTime / 1000,
			    tc.readHeldTime / 1000 ),

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 "%s,%s,%s,%s\n" % (
        	"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\n" % (
			t, c, 
			tt.readHeldTime/1000,
			tt.writeHeldTime/1000 ),

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 ):

	print "%s,%s,%s,%s,%s,%s,%s\n" % (
        	"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 sorted( s.byTable.iteritems(), key= lambda (k,v): -v.readWaitTime ):

                print "%s,%d,%d%%,%d,%d,%d%%,%d\n" % (
                        t, 
                        tc.readWaitTime/1000, 
			tc.readWaitTime * 100 / grandTotal.readWaitTime,
                        tc.readHeldTime/1000,
                        tc.writeWaitTime/1000,
                        tc.writeWaitTime * 100 / grandTotal.writeWaitTime,
                        tc.writeHeldTime/1000 ),

def main():

	# process args

	showLogging = 0
	showWaitVsHeld = 0
	showHisto = False
	showPages = False
	spannerInterval = 600
	submitOnly = False

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

	except getopt.error, msg:
		print msg
		print "Usage: p4clog.py [ -shlpwv ] [ -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 == '-l': showLogging = True
	    elif o == '-p': showPages = True
	    elif o == '-w': showWaitVsHeld = True
	    elif o == '-v': showWaitVsHeld = showLogging = showHisto = True

	# per table counts of held and wait times

	count = 0

	p = logParse()

	commandTables = {}

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

	grandTotal = tableCounts( 1, 1, 1, 1 ) # no divide by zero errors

	for line in sys.stdin:

		count += 1

		if( count % 1000000 == 0 ):
		    print >> sys.stderr, "%s\n" % count,

		# match one of the lines

		p.parse( line )

		# per table tallying

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

		# pages

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

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

		    continue

		# locks

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

		    # for interest sake

		    if( showLogging ):
			if( p.lrh > 100 ): print count, "readheld", p.table, p.lrh, p.command, p.args 
			if( p.lwh > 100 ): print count, "writeheld", p.table, p.lwh, p.command, p.args 
			if( p.lrw > 100 ): print count, "readwait", p.table, p.lrw, p.command, p.args 
			if( p.lww > 100 ): print count, "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
		    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, showLogging, count, p.command )

		    commandTables = {}

		    p.reset()

	# Dump it all out

	timesByTable.dump( grandTotal )

	timesByCommand.dump()

	waitVsHeld.dump( timesByTable.byTable )

	locksByTime.dump( spannerInterval )

main()