336 lines
13 KiB
Python
Executable File
336 lines
13 KiB
Python
Executable File
#!/usr/bin/python
|
|
|
|
#
|
|
# Copyright (c) 2016 Intel Corporation.
|
|
#
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
# you may not use this file except in compliance with the License.
|
|
# You may obtain a copy of the License at
|
|
#
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
#
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
# See the License for the specific language governing permissions and
|
|
# limitations under the License.
|
|
#
|
|
|
|
import os, sys, re
|
|
from collections import defaultdict
|
|
from optparse import OptionParser
|
|
|
|
class FilterTrace:
|
|
def __init__(self):
|
|
# 2 pass parsing
|
|
self.compiled_regexp = [] # regexp for 1st pass
|
|
self.compiled_regexp2 = [] # regexp for 2nd pass
|
|
self.final_text = [] # contains all lines before they are written to file
|
|
self.previous_line = {} # index in self.final_text of previous status change per
|
|
# tid + timestamp. So we can compute easily duration of
|
|
# state for 1 tid
|
|
|
|
# thread information
|
|
self.tid_names = {} # process name per tid
|
|
self.tid_states = defaultdict(int) # state per tid 0:RUNNING 1:QUEUED 2:SLEEPING
|
|
# 4:QUEUED or SLEEPING
|
|
|
|
# error checking per tid
|
|
self.t1_errors = defaultdict(int)
|
|
self.t2_errors = defaultdict(int)
|
|
self.t3_errors = defaultdict(int)
|
|
|
|
# context switch info
|
|
self.prev_tids = defaultdict(int) # previous tid per cpu when tracing new switch
|
|
|
|
# Time (relative and absolute)
|
|
self.last_timestamp_found = 0
|
|
self.last_timestamp = 0
|
|
self.reference_timestamp = 0 # time offset used in target script
|
|
self.convert = 1 / 1000.0 #1.0 / 1 * 1000 # 32kHz -> ms conversion
|
|
|
|
REGEXP_GLOSSARY = [
|
|
|
|
## irqs
|
|
# <idle>-0 [001] 294.876831: irq_handler_entry: irq=30 name=arch_timer
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<foo>[\w+\.]+)\s+(?P<timestamp>\d+\.\d+):\s+' \
|
|
'irq_handler_entry:\s+irq=(?P<irq_id>\d+)\s+name=(?P<irq_name>[\w \.-_]+).*$',
|
|
self.callback_irq_start_ftrace
|
|
],
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<timestamp>\d+\.\d+):\s+irq_handler_entry:' \
|
|
'\s+irq=(?P<irq_id>\d+)\s+name=(?P<irq_name>[\w \.-_]+).*$',
|
|
self.callback_irq_start_ftrace
|
|
],
|
|
# kworker/u:0-5 [000] 294.876862: irq_handler_exit: irq=30 ret=handled
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<foo>[\w+\.]+)\s+(?P<timestamp>\d+\.\d+):' \
|
|
'\s+irq_handler_exit:\s+irq=(?P<irq_id>\d+)\s+ret=.*$',
|
|
self.callback_irq_stop_ftrace
|
|
],
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<timestamp>\d+\.\d+):\s+irq_handler_exit:\s+' \
|
|
'irq=(?P<irq_id>\d+)\s+ret=.*$',
|
|
self.callback_irq_stop_ftrace
|
|
],
|
|
|
|
## scheduler
|
|
#sh-2505 [000] 271.147491: sched_switch: prev_comm=sh prev_pid=2505 prev_prio=120
|
|
# prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<foo>[\w+\.]+)\s+(?P<timestamp>\d+\.\d+):\s+' \
|
|
'sched_switch:\s+.*==>\s+next_comm=(?P<next_task_name>[\w \.#-_/]+)\s+' \
|
|
'next_pid=(?P<next_tid>\d+)\s+next_prio.*$',
|
|
self.callback_context_switch_ftrace
|
|
],
|
|
['^.*\[(?P<cpu_id>\d+)\]\s+(?P<timestamp>\d+\.\d+):\s+sched_switch:\s+.*==>\s+' \
|
|
'next_comm=(?P<next_task_name>[\w \.#-_/]+)\s+next_pid=(?P<next_tid>\d+)\s+' \
|
|
'next_prio.*$',
|
|
self.callback_context_switch_ftrace
|
|
],
|
|
['^TIMESTAMP.*$', None],
|
|
['^.*$', self.callback_no_rule]
|
|
]
|
|
|
|
REGEXP_GLOSSARY2 = [
|
|
['^Ref timestamp:\s*(?P<ref_time>\d+)$', self.callback_reference_timestamp],
|
|
['^.*psel.*$', None],
|
|
['^(?P<timestamp>\d+)\s+(?P<cpu_id>\d+)\s+(?P<task_name>[\w \.#-_/]+):(?P<tid>-?\d+)' \
|
|
'\s+(?P<state>\w+).*$',
|
|
self.callback_context_switch2
|
|
],
|
|
['^Last timestamp:\s*(?P<last_timestamp>\d+).*$', self.callback_end2],
|
|
['^.*$', self.callback_no_rule2]
|
|
]
|
|
|
|
# Compile all regexp
|
|
for regexp_string, regexp_rules in REGEXP_GLOSSARY:
|
|
self.compiled_regexp.append([re.compile(regexp_string), regexp_rules])
|
|
|
|
for regexp_string, regexp_rules in REGEXP_GLOSSARY2:
|
|
self.compiled_regexp2.append([re.compile(regexp_string), regexp_rules])
|
|
|
|
def filter_line(self, line):
|
|
# Parse all regexps
|
|
for regexp, regexp_rules in self.compiled_regexp:
|
|
# Test if regexp matches
|
|
res = regexp.search(line)
|
|
# if regexp match
|
|
if res:
|
|
# Execute regexp_rules
|
|
if regexp_rules:
|
|
regexp_rules(res, line)
|
|
# Only one regexp per line
|
|
break
|
|
|
|
def filter_line2(self):
|
|
# Parse self.final_text to add duration of state per tid
|
|
# Memorize index and timestamp of previous state change per tid and compute duration of
|
|
# previous state when new state change is seen
|
|
# For last state change, duration will be from state change until "Last timestamp"
|
|
for line_index in range(0, len(self.final_text)):
|
|
line = self.final_text[line_index]
|
|
|
|
for regexp, regexp_rules in self.compiled_regexp2:
|
|
# Test if regexp matches
|
|
res = regexp.search(line)
|
|
# if regexp match
|
|
if res:
|
|
# Execute regexp_rules
|
|
if regexp_rules:
|
|
regexp_rules(res, line_index)
|
|
# Only one regexp per line
|
|
break
|
|
|
|
|
|
|
|
def callback_context_switch_post(self, timestamp, cpu_id, next_tid, name, prev_tid,
|
|
prev_task_name, prev_state):
|
|
self.last_timestamp = timestamp
|
|
|
|
if (prev_task_name != ""):
|
|
self.tid_names[prev_tid] = prev_task_name
|
|
self.prev_tids[cpu_id] = prev_tid
|
|
|
|
# short format requires storage of previous running thread per core
|
|
if (cpu_id in self.prev_tids):
|
|
prev_tid = self.prev_tids[cpu_id]
|
|
|
|
if (prev_tid in self.tid_states):
|
|
if (self.tid_states[prev_tid] > 0): # goes to queue/sleep but was not running
|
|
# choice is to do as if running and we keep simply trace of that
|
|
self.t1_errors[prev_tid] += 1
|
|
|
|
if (prev_task_name != "") and (prev_state != ""):
|
|
if (res.group('prev_state') == 'R'):
|
|
self.tid_states[prev_tid] = 1 # queued
|
|
new_state = "Q"
|
|
else:
|
|
self.tid_states[prev_tid] = 2 # sleep
|
|
new_state = "S"
|
|
|
|
else:
|
|
self.tid_states[prev_tid] = 4 # Queued or sleep
|
|
new_state = "X"
|
|
|
|
# new state of previous thread if previous thread not seen for first time
|
|
self.final_text.append("%-10d %s %-16s:%-5s %s" % (self.last_timestamp,
|
|
cpu_id,
|
|
self.tid_names[prev_tid],
|
|
prev_tid,
|
|
new_state))
|
|
|
|
|
|
# handle "next task"
|
|
if (next_tid == 0):
|
|
next_tid = -cpu_id
|
|
if (name == "swapper"):
|
|
name += str(cpu_id)
|
|
self.tid_names[next_tid] = name
|
|
if (next_tid not in self.tid_states):
|
|
# consider was queued first time we see it to trigger no transition error
|
|
self.tid_states[next_tid] = 1
|
|
if (self.tid_states[next_tid] != 1): # process lifecycle: process must be queued to run
|
|
# goes running but was not queued (missing wakeup ?)
|
|
self.t2_errors[next_tid] += 1
|
|
|
|
self.tid_states[next_tid] = 0 # running
|
|
self.final_text.append("%-10s %s %-16s:%-5s R" % (self.last_timestamp,
|
|
cpu_id,
|
|
self.tid_names[next_tid],
|
|
next_tid))
|
|
self.prev_tids[cpu_id] = next_tid
|
|
|
|
def callback_context_switch_ftrace(self, res, line):
|
|
timestamp = int(float(res.group('timestamp')) * 1000.0)
|
|
if self.reference_timestamp == 0:
|
|
self.reference_timestamp = timestamp
|
|
timestamp = timestamp - self.reference_timestamp
|
|
cpu_id = int(res.group('cpu_id'))
|
|
name = res.group('next_task_name').rstrip(' ')
|
|
tid = int(res.group('next_tid'))
|
|
|
|
self.callback_context_switch_post(timestamp, cpu_id, tid, name, 0, "", "" )
|
|
|
|
def callback_irq_start_ftrace(self, res, line):
|
|
timestamp = int(float(res.group('timestamp')) * 1000.0)
|
|
if self.reference_timestamp == 0:
|
|
self.reference_timestamp = timestamp
|
|
timestamp = timestamp - self.reference_timestamp
|
|
cpu_id = int(res.group('cpu_id'))
|
|
irq_id = int(res.group('irq_id'))
|
|
irq_name = res.group('irq_name')
|
|
self.final_text.append("%d %d irqin %d unknown_func %s 0x0" % (timestamp,
|
|
cpu_id,
|
|
irq_id,
|
|
irq_name))
|
|
|
|
def callback_irq_stop_ftrace(self, res, line):
|
|
timestamp = int(float(res.group('timestamp')) * 1000.0)
|
|
if self.reference_timestamp == 0:
|
|
self.reference_timestamp = timestamp
|
|
timestamp = timestamp - self.reference_timestamp
|
|
cpu_id = int(res.group('cpu_id'))
|
|
irq_id = int(res.group('irq_id'))
|
|
self.final_text.append("%d %d irqout %d" % (timestamp, cpu_id, irq_id))
|
|
|
|
def callback_no_rule(self, res, line):
|
|
self.final_text.append(line.rstrip('\n'))
|
|
return
|
|
|
|
def callback_end(self, res, line):
|
|
if res != None:
|
|
self.final_text.append(line.rstrip('\n'))
|
|
else:
|
|
self.final_text.append("Last timestamp: %d" % self.last_timestamp)
|
|
|
|
self.last_timestamp_found = 1
|
|
|
|
print("\nT1: goes to queued/sleep but was not running")
|
|
keys = self.t1_errors.keys()
|
|
keys.sort()
|
|
for key in keys:
|
|
print("%s: %s %d") % (self.tid_names[key], key, self.t1_errors[key])
|
|
|
|
print("\nT2: goes running but was not queued (missing wakeup ?)")
|
|
keys = self.t2_errors.keys()
|
|
keys.sort()
|
|
for key in keys:
|
|
print("%s: %s %d") % (self.tid_names[key], key, self.t2_errors[key])
|
|
|
|
print("\nT3: wakes up but was not sleeping")
|
|
keys = self.t3_errors.keys()
|
|
keys.sort()
|
|
for key in keys:
|
|
print("%s: %s %d") % (self.tid_names[key], key, self.t3_errors[key])
|
|
|
|
def callback_context_switch2(self, res, line_index):
|
|
tid = int(res.group('tid'))
|
|
self.last_timestamp = int(res.group('timestamp'))
|
|
|
|
# per tid, go back to previous line, compute stamp current - previous stamp and add
|
|
# to previous line
|
|
if (tid in self.previous_line):
|
|
duration = self.last_timestamp - self.previous_line[tid][1]
|
|
self.final_text[self.previous_line[tid][0]] = \
|
|
self.final_text[self.previous_line[tid][0]] + \
|
|
" %-10d (%-10d %.3f ms)" % (duration,
|
|
self.previous_line[tid][1] + self.reference_timestamp,
|
|
self.previous_line[tid][1] * self.convert)
|
|
|
|
self.previous_line[tid] = [line_index, self.last_timestamp]
|
|
|
|
|
|
def callback_reference_timestamp(self, res, line_index):
|
|
self.reference_timestamp = int(res.group('ref_time'))
|
|
|
|
def callback_end2(self, res, line_index):
|
|
# add diff from last timestamp to current time to all tids
|
|
if res != None:
|
|
self.last_timestamp = int(res.group('last_timestamp'))
|
|
|
|
# add timing to end of file for last switch of all threads
|
|
for tid in self.previous_line:
|
|
last_duration = self.last_timestamp - self.previous_line[tid][1]
|
|
self.final_text[self.previous_line[tid][0]] = \
|
|
self.final_text[self.previous_line[tid][0]] + \
|
|
" %-10d (%-10d %.3f ms)" % (last_duration,
|
|
self.previous_line[tid][1] + self.reference_timestamp,
|
|
self.previous_line[tid][1] * self.convert)
|
|
|
|
# dump everything
|
|
print "\n%-9s %s %-15s:%-4s STA %-9s (%-10s)" % ("TIMESTAMP", "CPU", "NAME", "PID",
|
|
"DURATION", "ABS_TIME tick/REL_TIME ms")
|
|
for i in range(0, len(self.final_text)):
|
|
print self.final_text[i]
|
|
|
|
def callback_no_rule2(self, res, line_index):
|
|
return
|
|
|
|
global filterMaster
|
|
filterMaster = FilterTrace()
|
|
|
|
def Main(argv):
|
|
usage = "Usage: %prog FILENAME [options]"
|
|
parser = OptionParser(usage = usage)
|
|
(options, args) = parser.parse_args()
|
|
|
|
if len(args) != 1:
|
|
print "Usage: type python <program>.py -h"
|
|
return
|
|
|
|
# First pass, fill each array index with 1 thread + its new status + timestamp
|
|
# (basically 1 context switch will give 2 indexes, 1 wakeup 1 index)
|
|
# only missing info is duration of state
|
|
file = open(args[0], 'r')
|
|
string = file.readline()
|
|
|
|
while string:
|
|
filterMaster.filter_line(string)
|
|
string = file.readline()
|
|
|
|
if filterMaster.last_timestamp_found == 0:
|
|
filterMaster.callback_end(None, 0)
|
|
|
|
# 2nd pass, add duration of state of tid
|
|
filterMaster.filter_line2()
|
|
|
|
if __name__=="__main__":
|
|
Main(sys.argv[1:])
|