libvips/tools/vipsprofile

446 lines
13 KiB
Plaintext
Raw Normal View History

#!/usr/bin/python2
2013-11-19 11:13:38 +01:00
import re
2013-11-21 15:58:44 +01:00
import math
import cairo
2013-11-19 11:13:38 +01:00
class ReadFile:
def __init__(self, filename):
self.filename = filename
def __enter__(self):
self.f = open(self.filename, 'r')
self.lineno = 0
self.getnext();
return self
def __exit__(self, type, value, traceback):
self.f.close()
def __nonzero__(self):
return self.line != ""
def getnext(self):
self.lineno += 1
2013-11-25 15:45:06 +01:00
self.line = self.f.readline()
2013-11-19 11:13:38 +01:00
def read_times(rf):
times = []
while True:
match = re.match('[+-]?[0-9]+ ', rf.line)
2013-11-19 11:13:38 +01:00
if not match:
break
2013-11-20 22:35:18 +01:00
times += [int(x) for x in re.split(' ', rf.line.rstrip())]
2013-11-19 11:13:38 +01:00
rf.getnext()
return times[::-1]
2013-11-25 11:36:37 +01:00
class Thread:
thread_number = 0
def __init__(self, thread_name):
# no one cares about the thread address
match = re.match('(.*) \(0x.*?\) (.*)', thread_name)
if match:
thread_name = match.group(1) + " " + match.group(2)
2013-11-19 15:59:40 +01:00
self.thread_name = thread_name
2013-11-25 11:36:37 +01:00
self.thread_number = Thread.thread_number
2013-12-18 12:49:32 +01:00
self.all_events = []
self.workwait_events = []
self.memory_events = []
self.other_events = []
2013-11-25 11:36:37 +01:00
Thread.thread_number += 1
all_events = []
2013-11-25 11:36:37 +01:00
class Event:
2013-11-29 15:48:47 +01:00
def __init__(self, thread, gate_location, gate_name, start, stop):
2013-11-25 11:36:37 +01:00
self.thread = thread
2013-11-29 15:48:47 +01:00
self.gate_location = gate_location
2013-11-19 15:59:40 +01:00
self.gate_name = gate_name
2013-11-25 11:36:37 +01:00
self.work = False
self.wait = False
self.memory = False
if gate_location == "memory":
self.memory = True
elif re.match('.*work.*', gate_name):
2013-11-19 15:59:40 +01:00
self.work = True
elif re.match('.*wait.*', gate_name):
2013-11-19 15:59:40 +01:00
self.wait = True
if self.memory:
self.start = start
self.stop = start
self.size = stop
else:
self.start = start
self.stop = stop
2013-12-18 12:49:32 +01:00
thread.all_events.append(self)
all_events.append(self)
if self.wait or self.work:
2013-12-18 12:49:32 +01:00
thread.workwait_events.append(self)
elif self.memory:
2013-12-18 12:49:32 +01:00
thread.memory_events.append(self)
else:
2013-12-18 12:49:32 +01:00
thread.other_events.append(self)
2013-11-25 11:36:37 +01:00
2013-11-25 15:45:06 +01:00
input_filename = 'vips-profile.txt'
2013-11-21 15:58:44 +01:00
thread_id = 0
2013-11-25 11:36:37 +01:00
threads = []
n_events = 0
2013-11-25 15:45:06 +01:00
print 'reading from', input_filename
with ReadFile(input_filename) as rf:
2013-11-19 11:13:38 +01:00
while rf:
2013-11-25 15:45:06 +01:00
if rf.line.rstrip() == "":
rf.getnext()
continue
if rf.line[0] == "#":
rf.getnext()
continue
2013-11-21 15:58:44 +01:00
match = re.match('thread: (.*)', rf.line)
2013-11-19 11:13:38 +01:00
if not match:
print 'parse error line %d, expected "thread"' % rf.lineno
2013-11-21 15:58:44 +01:00
thread_name = match.group(1) + " " + str(thread_id)
thread_id += 1
2013-11-25 11:36:37 +01:00
thread = Thread(thread_name)
threads.append(thread)
2013-11-19 11:13:38 +01:00
rf.getnext()
while True:
match = re.match('^gate: (.*?)(: (.*))?$', rf.line)
2013-11-19 11:13:38 +01:00
if not match:
break
2013-11-29 15:48:47 +01:00
gate_location = match.group(1)
gate_name = match.group(3)
2013-11-19 11:13:38 +01:00
rf.getnext()
match = re.match('start:', rf.line)
if not match:
continue
rf.getnext()
2013-11-19 15:59:40 +01:00
start = read_times(rf)
2013-11-19 11:13:38 +01:00
match = re.match('stop:', rf.line)
if not match:
continue
rf.getnext()
2013-11-19 15:59:40 +01:00
stop = read_times(rf)
if len(start) != len(stop):
print 'start and stop length mismatch'
2013-11-20 22:35:18 +01:00
for a, b in zip(start, stop):
2013-11-29 15:48:47 +01:00
Event(thread, gate_location, gate_name, a, b)
2013-11-25 11:36:37 +01:00
n_events += 1
2013-11-20 22:35:18 +01:00
2013-11-25 11:36:37 +01:00
for thread in threads:
2013-12-18 12:49:32 +01:00
thread.all_events.sort(lambda x, y: cmp(x.start, y.start))
thread.workwait_events.sort(lambda x, y: cmp(x.start, y.start))
thread.memory_events.sort(lambda x, y: cmp(x.start, y.start))
thread.other_events.sort(lambda x, y: cmp(x.start, y.start))
2013-11-20 22:35:18 +01:00
all_events.sort(lambda x, y: cmp(x.start, y.start))
2013-11-25 11:36:37 +01:00
print 'loaded %d events' % n_events
2013-11-21 15:58:44 +01:00
# move time axis to secs of computation
2013-11-21 15:58:44 +01:00
ticks_per_sec = 1000000.0
first_time = all_events[0].start
2013-11-25 11:36:37 +01:00
last_time = 0
for event in all_events:
if event.start < first_time:
first_time = event.start
if event.stop > last_time:
last_time = event.stop
2013-11-21 15:58:44 +01:00
for event in all_events:
event.start = (event.start - first_time) / ticks_per_sec
event.stop = (event.stop - first_time) / ticks_per_sec
last_time = (last_time - first_time) / ticks_per_sec
first_time = 0
2013-12-18 12:49:32 +01:00
print 'total time =', last_time
2013-11-21 15:58:44 +01:00
# calculate some simple stats
for thread in threads:
thread.start = last_time
thread.stop = 0
thread.wait = 0
thread.work = 0
thread.mem = 0
thread.peak_mem = 0
2013-12-18 12:49:32 +01:00
for event in thread.all_events:
if event.start < thread.start:
thread.start = event.start
if event.stop > thread.stop:
thread.stop = event.stop
if event.wait:
thread.wait += event.stop - event.start
2013-11-26 18:53:44 +01:00
if event.work:
thread.work += event.stop - event.start
if event.memory:
thread.mem += event.size
if thread.mem > thread.peak_mem:
thread.peak_mem = thread.mem
thread.alive = thread.stop - thread.start
# hide very short-lived threads
thread.hide = thread.alive < 0.01
print 'name\t\talive\twait%\twork%\tunkn%\tmemory\tpeakm'
for thread in threads:
if thread.hide:
continue
wait_percent = 100 * thread.wait / thread.alive
work_percent = 100 * thread.work / thread.alive
unkn_percent = 100 - 100 * (thread.work + thread.wait) / thread.alive
print '%13s\t%6.2g\t' % (thread.thread_name, thread.alive),
print '%.3g\t%.3g\t%.3g\t' % (wait_percent, work_percent, unkn_percent),
print '%.3g\t' % (float(thread.mem) / (1024 * 1024)),
print '%.3g\t' % (float(thread.peak_mem) / (1024 * 1024))
mem = 0
peak_mem = 0
for event in all_events:
if event.memory:
mem += event.size
if mem > peak_mem:
peak_mem = mem
print 'peak memory = %.3g MB' % (float(peak_mem) / (1024 * 1024))
if mem != 0:
print 'leak! final memory = %.3g MB' % (float(mem) / (1024 * 1024))
# does a list of events contain an overlap?
# assume the list of events has been sorted by start time
def events_overlap(events):
for i in range(0, len(events) - 1):
2013-12-18 12:49:32 +01:00
# we can't just test for stop1 > start2 since one (or both) events
# might have duration zero
event1 = events[i]
event2 = events[i + 1]
overlap_start = max(event1.start, event2.start)
overlap_stop = min(event1.stop, event2.stop)
if overlap_stop - overlap_start > 0:
return True
2013-11-21 15:58:44 +01:00
return False
2013-11-25 11:36:37 +01:00
# do the events on two gates overlap?
def gates_overlap(events, gate_name1, gate_name2):
merged = []
for event in events:
if event.gate_name == gate_name1 or event.gate_name == gate_name2:
merged.append(event)
merged.sort(lambda x, y: cmp(x.start, y.start))
2013-11-25 11:36:37 +01:00
return events_overlap(merged)
2013-11-25 11:36:37 +01:00
# allocate a y position for each gate
total_y = 0
for thread in threads:
if thread.hide:
continue
2013-11-25 15:45:06 +01:00
thread.total_y = total_y
2013-11-25 11:36:37 +01:00
gate_positions = {}
# first pass .. move work and wait events to y == 0
2013-12-18 12:49:32 +01:00
if events_overlap(thread.workwait_events):
print 'gate overlap on thread', thread.thread_name
2013-12-18 12:49:32 +01:00
for i in range(0, len(thread.workwait_events) - 1):
event1 = thread.workwait_events[i]
event2 = thread.workwait_events[i + 1]
overlap_start = max(event1.start, event2.start)
overlap_stop = min(event1.stop, event2.stop)
if overlap_stop - overlap_start > 0:
print 'overlap:'
print 'event', event1.gate_location, event1.gate_name,
print 'starts at', event1.start, 'stops at', event1.stop
print 'event', event2.gate_location, event2.gate_name,
print 'starts at', event2.start, 'stops at', event2.stop
2013-12-18 12:49:32 +01:00
for event in thread.workwait_events:
gate_positions[event.gate_name] = 0
event.y = 0
event.total_y = total_y
2013-11-26 18:53:44 +01:00
2013-12-18 12:49:32 +01:00
for event in thread.memory_events:
gate_positions[event.gate_name] = 0
event.y = 0
event.total_y = total_y
2013-11-26 18:53:44 +01:00
# second pass: move all other events to non-overlapping ys
y = 1
2013-12-18 12:49:32 +01:00
for event in thread.other_events:
2013-11-26 18:53:44 +01:00
if not event.gate_name in gate_positions:
2013-11-28 11:45:31 +01:00
# look at all the ys we've allocated previously and see if we can
# add this gate to one of them
for gate_y in range(1, y):
found_overlap = False
for gate_name in gate_positions:
if gate_positions[gate_name] != gate_y:
continue
2013-12-18 12:49:32 +01:00
if gates_overlap(thread.other_events, event.gate_name, gate_name):
2013-11-28 11:45:31 +01:00
found_overlap = True
break
if not found_overlap:
gate_positions[event.gate_name] = gate_y
2013-11-25 11:36:37 +01:00
break
2013-11-28 11:45:31 +01:00
# failure? add a new y
if not event.gate_name in gate_positions:
2013-11-25 11:36:37 +01:00
gate_positions[event.gate_name] = y
y += 1
event.y = gate_positions[event.gate_name]
2013-11-28 11:45:31 +01:00
# third pass: flip the order of the ys to get the lowest-level ones at the
# top, next to the wait/work line
2013-12-18 12:49:32 +01:00
for event in thread.other_events:
2013-11-28 11:45:31 +01:00
event.y = y - event.y
2013-11-25 15:45:06 +01:00
event.total_y = total_y + event.y
2013-11-25 11:36:37 +01:00
total_y += y
PIXELS_PER_SECOND = 1000
PIXELS_PER_GATE = 20
LEFT_BORDER = 130
2013-11-25 15:45:06 +01:00
BAR_HEIGHT = 5
MEM_HEIGHT = 100
WIDTH = int(LEFT_BORDER + last_time * PIXELS_PER_SECOND) + 20
HEIGHT = int(total_y * PIXELS_PER_GATE) + MEM_HEIGHT + 30
2013-11-25 15:45:06 +01:00
output_filename = "vips-profile.svg"
print 'writing to', output_filename
surface = cairo.SVGSurface(output_filename, WIDTH, HEIGHT)
2013-11-25 15:45:06 +01:00
ctx = cairo.Context(surface)
ctx.select_font_face('Sans')
ctx.set_font_size(15)
ctx.rectangle(0, 0, WIDTH, HEIGHT)
ctx.set_source_rgba(0.0, 0.0, 0.3, 1.0)
ctx.fill()
2013-11-25 15:45:06 +01:00
def draw_event(ctx, event):
left = event.start * PIXELS_PER_SECOND + LEFT_BORDER
top = event.total_y * PIXELS_PER_GATE + BAR_HEIGHT / 2
width = (event.stop - event.start) * PIXELS_PER_SECOND
2013-11-25 15:45:06 +01:00
height = BAR_HEIGHT
if event.memory:
width = 1
height /= 2
top += BAR_HEIGHT
2013-11-25 15:45:06 +01:00
ctx.rectangle(left, top, width, height)
if event.wait:
ctx.set_source_rgb(0.9, 0.1, 0.1)
elif event.work:
ctx.set_source_rgb(0.1, 0.9, 0.1)
elif event.memory:
ctx.set_source_rgb(1.0, 1.0, 1.0)
2013-11-25 15:45:06 +01:00
else:
ctx.set_source_rgb(0.1, 0.1, 0.9)
ctx.fill()
if not event.wait and not event.work and not event.memory:
2013-11-25 15:45:06 +01:00
xbearing, ybearing, twidth, theight, xadvance, yadvance = \
2013-11-29 15:48:47 +01:00
ctx.text_extents(event.gate_name)
2013-11-29 10:40:54 +01:00
ctx.move_to(left + width / 2 - twidth / 2, top + 3 * BAR_HEIGHT)
2013-11-25 15:45:06 +01:00
ctx.set_source_rgb(1.00, 0.83, 0.00)
2013-11-29 15:48:47 +01:00
ctx.show_text(event.gate_name)
2013-11-21 15:58:44 +01:00
2013-11-25 11:36:37 +01:00
for thread in threads:
if thread.hide:
continue
ctx.rectangle(0, thread.total_y * PIXELS_PER_GATE, WIDTH, 1)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.fill()
2013-11-25 15:45:06 +01:00
xbearing, ybearing, twidth, theight, xadvance, yadvance = \
ctx.text_extents(thread.thread_name)
ctx.move_to(0, theight + thread.total_y * PIXELS_PER_GATE + BAR_HEIGHT / 2)
2013-11-25 15:45:06 +01:00
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.show_text(thread.thread_name)
2013-12-18 12:49:32 +01:00
for event in thread.all_events:
2013-11-25 15:45:06 +01:00
draw_event(ctx, event)
2013-11-25 12:01:09 +01:00
2013-12-09 16:14:54 +01:00
memory_y = total_y * PIXELS_PER_GATE
label = "memory"
xbearing, ybearing, twidth, theight, xadvance, yadvance = \
ctx.text_extents(label)
ctx.move_to(0, memory_y + theight + 8)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.show_text(label)
mem = 0
2013-12-09 16:14:54 +01:00
ctx.move_to(LEFT_BORDER, memory_y + MEM_HEIGHT)
for event in all_events:
if event.memory:
mem += event.size
left = LEFT_BORDER + event.start * PIXELS_PER_SECOND
top = memory_y + MEM_HEIGHT - (MEM_HEIGHT * mem / peak_mem)
2013-12-09 16:14:54 +01:00
ctx.line_to(left, top)
ctx.set_line_width(1)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.stroke()
axis_y = total_y * PIXELS_PER_GATE + MEM_HEIGHT
ctx.rectangle(LEFT_BORDER, axis_y, last_time * PIXELS_PER_SECOND, 1)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.fill()
label = "time"
xbearing, ybearing, twidth, theight, xadvance, yadvance = \
ctx.text_extents(label)
ctx.move_to(0, axis_y + theight + 8)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.show_text(label)
for t in range(0, int(last_time * PIXELS_PER_SECOND), PIXELS_PER_SECOND / 10):
left = t + LEFT_BORDER
top = axis_y
ctx.rectangle(left, top, 1, 5)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.fill()
label = str(float(t) / PIXELS_PER_SECOND)
xbearing, ybearing, twidth, theight, xadvance, yadvance = \
ctx.text_extents(label)
ctx.move_to(left - twidth / 2, top + theight + 8)
ctx.set_source_rgb(1.00, 1.00, 1.00)
ctx.show_text(label)
surface.finish()