tracer/gsttr-stats.py

   1 #!/usr/bin/env python3
   2 '''
   3 Aggregate values for each tracer event type and print them with some statistics.
   4
   5 How to run:
   6 1) generate some log
   7 GST_DEBUG="GST_TRACER:7" GST_TRACERS="stats;rusage;latency" GST_DEBUG_FILE=trace.log <application>
   8
   9 2) print everything
  10 python3 gsttr-stats.py trace.log
  11
  12 3) print selected entries only
  13 python3 gsttr-stats.py -c latency trace.log
  14 '''
  15 # TODO:
  16 # more options
  17 # - live-update interval (for file=='-')
  18 #
  19 # - for values like timestamps, we only want min/max but no average
  20
  21 import logging
  22 from fnmatch import fnmatch
  23 from tracer.analysis_runner import AnalysisRunner
  24 from tracer.analyzer import Analyzer
  25 from tracer.parser import Parser
  26 from tracer.structure import Structure
  27
  28
  29 logging.basicConfig(level=logging.WARNING)
  30 logger = logging.getLogger('gsttr-stats')
  31
  32 _SCOPE_RELATED_TO = {
  33     'GST_TRACER_VALUE_SCOPE_PAD': 'Pad',
  34     'GST_TRACER_VALUE_SCOPE_ELEMENT': 'Element',
  35     'GST_TRACER_VALUE_SCOPE_THREAD': 'Thread',
  36     'GST_TRACER_VALUE_SCOPE_PROCESS': 'Process',
  37 }
  38
  39 _NUMERIC_TYPES = ('int', 'uint', 'gint', 'guint', 'gint64', 'guint64')
  40
  41
  42 class Stats(Analyzer):
  43
  44     def __init__(self, classes):
  45         super(Stats, self).__init__()
  46         self.classes = classes
  47         self.records = {}
  48         self.data = {}
  49
  50     def handle_tracer_class(self, event):
  51         s = Structure(event[Parser.F_MESSAGE])
  52         # TODO only for debugging
  53         # print("tracer class:", repr(s))
  54         name = s.name[:-len('.class')]
  55         record = {
  56             'class': s,
  57             'scope': {},
  58             'value': {},
  59         }
  60         self.records[name] = record
  61         for k, v in s.values.items():
  62             if v.name == 'scope':
  63                 # TODO only for debugging
  64                 # print("scope: [%s]=%s" % (k, v))
  65                 record['scope'][k] = v
  66             elif v.name == 'value':
  67                 # skip non numeric and those without min/max
  68                 if v.values['type'] in _NUMERIC_TYPES and 'min' in v.values and 'max' in v.values:
  69                     # TODO only for debugging
  70                     # print("value: [%s]=%s" % (k, v))
  71                     record['value'][k] = v
  72                 # else:
  73                     # TODO only for debugging
  74                     # print("skipping value: [%s]=%s" % (k, v))
  75
  76     def handle_tracer_entry(self, event):
  77         # use first field in message (structure-id) if none
  78         if event[Parser.F_FUNCTION]:
  79             return
  80
  81         msg = event[Parser.F_MESSAGE]
  82         p = msg.find(',')
  83         if p == -1:
  84             return
  85
  86         entry_name = msg[:p]
  87         if self.classes:
  88             if not any([fnmatch(entry_name, c) for c in self.classes]):
  89                 return
  90
  91         record = self.records.get(entry_name)
  92         if not record:
  93             return
  94
  95         try:
  96             s = Structure(msg)
  97         except ValueError:
  98             logger.warning("failed to parse: '%s'", msg)
  99             return
 100
 101         # aggregate event based on class
 102         for sk, sv in record['scope'].items():
 103             # look up bin by scope (or create new)
 104             key = (_SCOPE_RELATED_TO[sv.values['related-to']] + ":" + str(s.values[sk]))
 105             scope = self.data.get(key)
 106             if not scope:
 107                 scope = {}
 108                 self.data[key] = scope
 109             for vk, vv in record['value'].items():
 110                 # skip optional fields
 111                 if vk not in s.values:
 112                     continue
 113                 if not s.values.get('have-' + vk, True):
 114                     continue
 115
 116                 key = entry_name + "/" + vk
 117                 data = scope.get(key)
 118                 if not data:
 119                     data = {'num': 0}
 120                     if '_FLAGS_AGGREGATED' not in vv.values.get('flags', ''):
 121                         data['sum'] = 0
 122                         if 'max' in vv.values and 'min' in vv.values:
 123                             data['min'] = int(vv.values['max'])
 124                             data['max'] = int(vv.values['min'])
 125                     else:
 126                         # aggregated: don't average, collect first value
 127                         data['min'] = int(s.values[vk])
 128                     scope[key] = data
 129                 # update min/max/sum and count via value
 130                 dv = int(s.values[vk])
 131                 data['num'] += 1
 132                 if 'sum' in data:
 133                     data['sum'] += dv
 134                     if 'min' in data:
 135                         data['min'] = min(dv, data['min'])
 136                     if 'max' in data:
 137                         data['max'] = max(dv, data['max'])
 138                 else:
 139                     # aggregated: collect last value
 140                     data['max'] = dv
 141
 142     def report(self):
 143         # headline
 144         print("%-45s: %30s: %16s/%16s/%16s" % (
 145             'scope', 'value', 'min', 'avg', 'max'))
 146         # iterate scopes
 147         for sk, sv in self.data.items():
 148             # iterate tracers
 149             for tk, tv in sv.items():
 150                 mi = tv.get('min', '-')
 151                 ma = tv.get('max', '-')
 152                 if 'sum' in tv:
 153                     avg = tv['sum'] / tv['num']
 154                 else:
 155                     avg = '-'
 156                 if mi == ma:
 157                     mi = ma = '-'
 158                 if is_time_field(tk):
 159                     if mi != '-':
 160                         mi = format_ts(mi)
 161                     if ma != '-':
 162                         ma = format_ts(ma)
 163                     if avg != '-':
 164                         avg = format_ts(avg)
 165                 print("%-45s: %30s: %16s/%16s/%16s" % (sk, tk, mi, avg, ma))
 166
 167
 168 class ListClasses(Analyzer):
 169
 170     def __init__(self):
 171         super(ListClasses, self).__init__()
 172
 173     def handle_tracer_class(self, event):
 174         s = Structure(event[Parser.F_MESSAGE])
 175         print(s.name)
 176
 177     def handle_tracer_entry(self, event):
 178         raise StopIteration
 179
 180
 181 def format_ts(ts):
 182     sec = 1e9
 183     h = int(ts // (sec * 60 * 60))
 184     m = int((ts // (sec * 60)) % 60)
 185     s = (ts / sec)
 186     return '{:02d}:{:02d}:{:010.7f}'.format(h, m, s)
 187
 188
 189 def is_time_field(f):
 190     # TODO: need proper units
 191     return (f.endswith('/time') or f.endswith('-dts') or f.endswith('-pts')
 192         or f.endswith('-duration'))
 193
 194
 195 if __name__ == '__main__':
 196     import argparse
 197     parser = argparse.ArgumentParser()
 198     parser.add_argument('file', nargs='?', default='debug.log')
 199     parser.add_argument('-c', '--class', action='append', dest='classes',
 200                         help='tracer class selector (default: all)')
 201     parser.add_argument('-l', '--list-classes', action='store_true',
 202                         help='show tracer classes')
 203     args = parser.parse_args()
 204
 205     analyzer = None
 206     if args.list_classes:
 207         analyzer = ListClasses()
 208     else:
 209         analyzer = stats = Stats(args.classes)
 210
 211     with Parser(args.file) as log:
 212         runner = AnalysisRunner(log)
 213         runner.add_analyzer(analyzer)
 214         runner.run()
 215
 216     if not args.list_classes:
 217         stats.report()