1#!/usr/bin/env python 2 3# Copyright (C) 2024 The Android Open Source Project 4# 5# Licensed under the Apache License, Version 2.0 (the "License"); 6# you may not use this file except in compliance with the License. 7# You may obtain a copy of the License at 8# 9# http://www.apache.org/licenses/LICENSE-2.0 10# 11# Unless required by applicable law or agreed to in writing, software 12# distributed under the License is distributed on an "AS IS" BASIS, 13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14# See the License for the specific language governing permissions and 15# limitations under the License. 16 17"""Parses PSI dump from psi_monitor to psi CSV and logcat to events CSV.""" 18import argparse 19import datetime 20import os 21import pandas as pd 22import re 23import time 24 25from typing import Any, Dict, List, Tuple 26 27# Sample psi_monitor line: 28# 13980 2024-09-06_10:18:38 cpu:some avg10=4.39 avg60=1.29 avg300=0.29 total=1462999 \ 29# cpu:full avg10=0.00 avg60=0.00 avg300=0.00 total=0 \ 30# io:some avg10=3.29 avg60=0.87 avg300=0.19 total=737543 \ 31# io:full avg10=2.05 avg60=0.54 avg300=0.12 total=455996 \ 32# irq:full avg10=0.32 avg60=0.06 avg300=0.01 total=90937 \ 33# memory:some avg10=0.00 avg60=0.00 avg300=0.00 total=0 \ 34# memory:full avg10=0.00 avg60=0.00 avg300=0.00 total=0 35 36TIMESTAMP_PATTERN = (r'(?P<uptime_millis>\d+)' 37 # Drop the nanoseconds part of the timestamp because the python datetime 38 # library supports parsing only up to microseconds. 39 r'\s+(?P<local_datetime>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{6})\d{3}') 40CPU_SOME_PATTERN= (r'cpu:some\s+avg10=(?P<cpu_some_avg10>\d+\.?\d+)\s+' 41 r'avg60=(?P<cpu_some_avg60>\d+\.?\d+)\s+avg300=(?P<cpu_some_avg300>\d+\.?\d+)' 42 r'\s+total=(?P<cpu_some_total>\d+)') 43CPU_FULL_PATTERN = (r'cpu:full\s+avg10=(?P<cpu_full_avg10>\d+\.?\d+)\s+' 44 r'avg60=(?P<cpu_full_avg60>\d+\.?\d+)\s+avg300=(?P<cpu_full_avg300>\d+\.?\d+)' 45 r'\s+total=(?P<cpu_full_total>\d+)') 46IO_SOME_PATTERN = (r'io:some\s+avg10=(?P<io_some_avg10>\d+\.?\d+)\s+' 47 r'avg60=(?P<io_some_avg60>\d+\.?\d+)\s+avg300=(?P<io_some_avg300>\d+\.?\d+)' 48 r'\s+total=(?P<io_some_total>\d+)') 49IO_FULL_PATTERN = (r'io:full\s+avg10=(?P<io_full_avg10>\d+\.?\d+)\s+' 50 r'avg60=(?P<io_full_avg60>\d+\.?\d+)\s+avg300=(?P<io_full_avg300>\d+\.?\d+)' 51 r'\s+total=(?P<io_full_total>\d+)') 52IRQ_FULL_PATTERN = (r'irq:full\s+avg10=(?P<irq_full_avg10>\d+\.?\d+)\s+' 53 r'avg60=(?P<irq_full_avg60>\d+\.?\d+)\s+avg300=(?P<irq_full_avg300>\d+\.?\d+)' 54 r'\s+total=(?P<irq_full_total>\d+)') 55MEMORY_SOME_PATTERN = (r'memory:some\s+avg10=(?P<memory_some_avg10>\d+\.?\d+)\s+' 56 r'avg60=(?P<memory_some_avg60>\d+\.?\d+)\s+' 57 r'avg300=(?P<memory_some_avg300>\d+\.?\d+)\s+' 58 r'total=(?P<memory_some_total>\d+)') 59MEMORY_FULL_PATTERN = (r'memory:full\s+avg10=(?P<memory_full_avg10>\d+\.?\d+)\s+' 60 r'avg60=(?P<memory_full_avg60>\d+\.?\d+)\s+' 61 r'avg300=(?P<memory_full_avg300>\d+\.?\d+)\s+' 62 r'total=(?P<memory_full_total>\d+)') 63EVENT_DESCRIPTION_PATTERN = (r'(?:\s+\"(?P<event_descriptions>.*)\")?') 64PSI_LINE_RE = re.compile(r'^' + TIMESTAMP_PATTERN + r'\s+' + CPU_SOME_PATTERN 65 # CPU full is optional because it is not always reported by the Kernel. 66 + r'(?:\s+' + CPU_FULL_PATTERN + r')?\s+' 67 + IO_SOME_PATTERN + r'\s+' + IO_FULL_PATTERN 68 # IRQ full is optional because it is not always reported by the Kernel. 69 + r'(?:\s+' + IRQ_FULL_PATTERN + r')?\s+' 70 + MEMORY_SOME_PATTERN + r'\s+' + MEMORY_FULL_PATTERN 71 + EVENT_DESCRIPTION_PATTERN + '$') 72PSI_OUT_FIELDS = ['uptime_millis', 'local_datetime', 'epoch_millis', 73 'monitor_start_relative_millis', 'cpu_some_avg10', 'cpu_some_avg60', 74 'cpu_some_avg300', 'cpu_some_total', 'cpu_full_avg10', 'cpu_full_avg60', 75 'cpu_full_avg300', 'cpu_full_total', 'io_some_avg10', 'io_some_avg60', 76 'io_some_avg300', 'io_some_total', 'io_full_avg10', 'io_full_avg60', 77 'io_full_avg300', 'io_full_total', 'irq_full_avg10', 'irq_full_avg60', 78 'irq_full_avg300', 'irq_full_total', 'memory_some_avg10', 'memory_some_avg60', 79 'memory_some_avg300', 'memory_some_total', 'memory_full_avg10', 80 'memory_full_avg60', 'memory_full_avg300', 'memory_full_total', 81 'event_descriptions'] 82 83# Supported logcat lines: 84# 1. 2024-09-26 09:19:56.140 1627 1805 I ActivityTaskManager: START u0 85# {act=android.intent.action.MAIN cmp=com.android.car.cluster.home/.ClusterHomeActivityLightMode} 86# with LAUNCH_SINGLE_TASK from uid 1000 (BAL_ALLOW_ALLOWLISTED_UID) result code=0 87# 2. 2024-09-26 09:19:56.675 1627 1811 I ActivityTaskManager: Displayed 88# com.android.car.cluster.home/.ClusterHomeActivityLightMode for user 0: +262ms 89# 3. 2024-09-26 09:19:56.097 1627 1822 D SystemServerTimingAsync: ssm.UnlockingUser-0 90# 4. 2024-09-26 09:19:56.144 1627 1822 V SystemServerTimingAsync: ssm.UnlockingUser-0 took to 91# complete: 47ms 92LOGCAT_TIMESTAMP_PATTERN = r'(?P<local_datetime>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3})' 93PID_TID_LOGLEVEL_PATTERN = r'(?P<pid>\d+)\s+(?P<tid>\d+)\s+(?P<loglevel>[VDIWEFS])' 94ACTIVITY_TASK_MANAGER_TAG = 'ActivityTaskManager' 95ACTIVITY_TASK_MANAGER_START_PATTERN = (ACTIVITY_TASK_MANAGER_TAG + r':\s+START\s+u(?P<user_id>\d+)' 96 r'\s+\{.*cmp=(?P<activity_name>[0-9A-Za-z\.\/]+)(:?\s+|\})' 97 r'.*') 98ACTIVITY_TASK_MANAGER_DISPLAYED_PATTERN = (ACTIVITY_TASK_MANAGER_TAG + r':\s+Displayed\s+' 99 r'(?P<activity_name>.*)\s+for\s+user\s+' 100 r'(?P<user_id>\d+):\s+\+(:?(?P<duration_secs>\d+)s)?' 101 r'(?P<duration_millis>\d+)ms') 102SYSTEM_SERVER_TIMING_ASYNC_TAG = 'SystemServerTimingAsync' 103SYSTEM_SERVER_TIMING_ASYNC_PATTERN = (SYSTEM_SERVER_TIMING_ASYNC_TAG 104 + r': (?P<event_description>.*)') 105SYSTEM_SERVER_TIMING_ASYNC_COMPLETE_PATTERN = (SYSTEM_SERVER_TIMING_ASYNC_TAG 106 + r': (?P<event_description>.*)' 107 r'\s+took to complete:\s+(?P<duration_millis>\d+)ms') 108 109ACTIVITY_TASK_MANAGER_START_LINE_RE = re.compile(r'^' + LOGCAT_TIMESTAMP_PATTERN + r'\s+' 110 + PID_TID_LOGLEVEL_PATTERN + r'\s+' 111 + ACTIVITY_TASK_MANAGER_START_PATTERN 112 + '$') 113ACTIVITY_TASK_MANAGER_DISPLAYED_LINE_RE = re.compile(r'^' + LOGCAT_TIMESTAMP_PATTERN + r'\s+' 114 + PID_TID_LOGLEVEL_PATTERN + r'\s+' 115 + ACTIVITY_TASK_MANAGER_DISPLAYED_PATTERN 116 + '$') 117SYSTEM_SERVER_TIMING_ASYNC_LINE_RE = re.compile(r'^' + LOGCAT_TIMESTAMP_PATTERN + r'\s+' 118 + PID_TID_LOGLEVEL_PATTERN + r'\s+' 119 + SYSTEM_SERVER_TIMING_ASYNC_PATTERN 120 + '$') 121SYSTEM_SERVER_TIMING_ASYNC_COMPLETE_LINE_RE = re.compile(r'^' + LOGCAT_TIMESTAMP_PATTERN + r'\s+' 122 + PID_TID_LOGLEVEL_PATTERN + r'\s+' 123 + SYSTEM_SERVER_TIMING_ASYNC_COMPLETE_PATTERN 124 + '$') 125ACTIVITY_DISPLAYED_DURATION_THRESHOLD_MILLIS = 1000 126SS_EVENT_MIN_DURATION_TO_PLOT_MILLIS = 50 127SS_EVENT_DURATION_THRESHOLD_MILLIS = 250 128EVENTS_OUT_FIELDS = ['epoch_millis', 'monitor_start_relative_millis', 129 # event_tag is the logcat tag reported in the logcat. This can be used to 130 # filter events with the same tag. 131 # event_description contains the timing information for the event, which 132 # can be used when plotting the events in charts. 133 # event_key contains a unique key for the event, which can be used to 134 # gather statistics of events across multiple runs of a CUJ. 135 'event_tag', 'event_description', 'event_key', 'duration_value', 136 'is_high_latency_event', 'color', 'should_plot'] 137MIN_DURATION_MILLIS_DELTA_BEFORE_MONITOR_START = -600000 # 10 minutes 138 139 140def parse_psi_line(line) -> Dict[str, str]: 141 m = PSI_LINE_RE.match(line) 142 assert m, 'Failed to parse PSI line: {}\n\nFormat: {}'.format(line, PSI_LINE_RE.pattern) 143 return m.groupdict() 144 145 146def on_psi_field_missing(field, line) -> str: 147 if field.endswith('_avg10') or field.endswith('_avg60') or field.endswith('_avg300'): 148 return str(0.0) 149 elif field.endswith('_total'): 150 return str(0) 151 elif field == 'event_descriptions': 152 return list() 153 else: 154 raise ValueError('Unknown field: {} in line: {}'.format(field, line)) 155 156 157def get_epoch_milliseconds(date_string, format='%Y-%m-%d %H:%M:%S.%f'): 158 try: 159 datetime_obj = datetime.datetime.strptime(date_string, format) 160 return int((time.mktime(datetime_obj.timetuple()) * 1000) + datetime_obj.microsecond / 1000) 161 except ValueError as e: 162 print("Error parsing date '{}': {}".format(date_string, e)) 163 return 0 164 165 166def parse_psi_dump(psi_dump_file) -> Tuple[pd.DataFrame, int]: 167 with open(psi_dump_file, 'r') as f: 168 dump = f.readlines() 169 for i in range(len(dump)): 170 dump[i] = dump[i].strip() 171 monitor_start_uptime_millis = None 172 monitor_start_epoch_millis = None 173 psi_df = pd.DataFrame(columns=PSI_OUT_FIELDS) 174 for line in dump: 175 psi_dict = parse_psi_line(line) 176 psi_dict['epoch_millis'] = str(get_epoch_milliseconds(psi_dict['local_datetime'])) 177 if not monitor_start_uptime_millis: 178 monitor_start_uptime_millis = int(psi_dict['uptime_millis']) 179 monitor_start_epoch_millis = int(psi_dict['epoch_millis']) 180 psi_dict['monitor_start_relative_millis'] = str(0) 181 else: 182 psi_dict['monitor_start_relative_millis'] = str( 183 int(psi_dict['uptime_millis']) - monitor_start_uptime_millis) 184 if psi_dict['event_descriptions']: 185 # Handle the case where multiple events are reported on the same line 186 if '" "' in psi_dict['event_descriptions']: 187 psi_dict['event_descriptions'] = psi_dict['event_descriptions'].replace( 188 "\" \"", ",").split(",") 189 else: 190 psi_dict['event_descriptions'] = [psi_dict['event_descriptions']] 191 out_line = [psi_dict[field] if field in psi_dict and psi_dict[field] 192 else on_psi_field_missing(field, line) for field in PSI_OUT_FIELDS] 193 psi_df.loc[len(psi_df)] = out_line 194 return psi_df, monitor_start_epoch_millis 195 196 197class LogcatParser: 198 def __init__(self, logcat_file, monitor_start_epoch_millis): 199 self._event_counts_dict = {} 200 self._logcat_file = logcat_file 201 self._monitor_start_epoch_millis = monitor_start_epoch_millis 202 203 204 def _get_list(self, epoch_millis, event_tag, event_description, color, event_key=None, 205 duration_millis=None, is_high_latency_event=False, should_plot=True): 206 if event_key: 207 if event_key in self._event_counts_dict: 208 self._event_counts_dict[event_key] += 1 209 event_key += ': Occurrence {}'.format(self._event_counts_dict[event_key]) 210 else: 211 self._event_counts_dict[event_key] = 1 212 monitor_start_relative_millis = int(epoch_millis - self._monitor_start_epoch_millis) 213 # Some logcat entries will have incorrect timestamps. Discard such entries to avoid downstream 214 # issues. 215 if monitor_start_relative_millis < MIN_DURATION_MILLIS_DELTA_BEFORE_MONITOR_START: 216 return None 217 return [int(epoch_millis), monitor_start_relative_millis, event_tag, 218 event_description, event_key, duration_millis, is_high_latency_event, color, 219 should_plot] 220 221 222 def _parse_line(self, line) -> List[Any]: 223 m = ACTIVITY_TASK_MANAGER_START_LINE_RE.match(line) 224 if m: 225 matched = m.groupdict() 226 return self._get_list(get_epoch_milliseconds(matched['local_datetime']), 227 ACTIVITY_TASK_MANAGER_TAG, 228 ('Started ' + matched['activity_name'] + ' for user ' + matched['user_id']), 'lime') 229 m = ACTIVITY_TASK_MANAGER_DISPLAYED_LINE_RE.match(line) 230 if m: 231 matched = m.groupdict() 232 if 'duration_secs' in matched and matched['duration_secs']: 233 duration_millis = (int(matched['duration_secs']) * 1000) + int(matched['duration_millis']) 234 else: 235 duration_millis = int(matched['duration_millis']) 236 event_key = 'Displayed ' + matched['activity_name'] + ' for user ' + matched['user_id'] 237 return self._get_list(get_epoch_milliseconds(matched['local_datetime']), 238 ACTIVITY_TASK_MANAGER_TAG, (event_key + ' took ' + str(duration_millis) + 'ms'), 239 'orangered' if duration_millis >= ACTIVITY_DISPLAYED_DURATION_THRESHOLD_MILLIS else 'green', 240 event_key, duration_millis, 241 is_high_latency_event=(duration_millis >= ACTIVITY_DISPLAYED_DURATION_THRESHOLD_MILLIS)) 242 m = SYSTEM_SERVER_TIMING_ASYNC_COMPLETE_LINE_RE.match(line) 243 if m: 244 matched = m.groupdict() 245 duration_millis = int(matched['duration_millis']) 246 event_key = 'SystemServer event ' + matched['event_description'] 247 return self._get_list(get_epoch_milliseconds(matched['local_datetime']), 248 SYSTEM_SERVER_TIMING_ASYNC_TAG, (event_key + ' took ' + str(duration_millis) + 'ms'), 249 'red' if duration_millis >= SS_EVENT_DURATION_THRESHOLD_MILLIS else 'saddlebrown', 250 event_key, duration_millis, 251 is_high_latency_event=duration_millis >= SS_EVENT_DURATION_THRESHOLD_MILLIS, 252 should_plot=duration_millis >= SS_EVENT_MIN_DURATION_TO_PLOT_MILLIS) 253 m = SYSTEM_SERVER_TIMING_ASYNC_LINE_RE.match(line) 254 if m: 255 matched = m.groupdict() 256 return self._get_list(get_epoch_milliseconds(matched['local_datetime']), 257 SYSTEM_SERVER_TIMING_ASYNC_TAG, ('SystemServer event ' + matched['event_description']), 258 'yellow') 259 return None 260 261 262 def get_events_df(self) -> pd.DataFrame: 263 events_df = pd.DataFrame(columns=EVENTS_OUT_FIELDS) 264 with open(self._logcat_file, 'r') as f: 265 logcat = f.readlines() 266 for line in logcat: 267 row = self._parse_line(line.strip()) 268 if row: 269 events_df.loc[len(events_df)] = row 270 return events_df 271 272 273def main(): 274 parser = argparse.ArgumentParser(description='Parse PSI dump from psi_monitor.') 275 parser.add_argument('--psi_dump', action='store', type=str, required=True, dest='psi_dump', 276 help='PSI dump from psi_monitor.sh') 277 parser.add_argument('--logcat', action='store', type=str, required=False, dest='logcat', 278 help='Logcat from run_cuj.sh') 279 parser.add_argument('--psi_csv', action='store', type=str, required=True, dest='psi_csv', 280 help='Output CSV file') 281 parser.add_argument('--events_csv', action='store', type=str, dest='events_csv', 282 help='Output events CSV file. Generated only when logcat is provided.') 283 args = parser.parse_args() 284 print('Converting PSI dump {} to CSV {}'.format(args.psi_dump, args.psi_csv)) 285 psi_df, monitor_start_epoch_millis = parse_psi_dump(args.psi_dump) 286 psi_df.to_csv(args.psi_csv, index=False) 287 288 if args.logcat: 289 events_csv = args.events_csv if args.events_csv else (os.path.dirname(args.psi_csv) 290 + '/events.csv') 291 print('Parsing events from logcat {} to CSV {}'.format(args.logcat, events_csv)) 292 logcat_parser = LogcatParser(args.logcat, monitor_start_epoch_millis) 293 events_df = logcat_parser.get_events_df() 294 events_df.to_csv(events_csv, index=False) 295 296if __name__ == '__main__': 297 main() 298