1#!/usr/bin/env python3 2# -*- coding: UTF-8 -*- 3 4# Copyright (c) 2023 Huawei Device Co., Ltd. 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 17import os 18import re 19import argparse 20import stat 21import copy 22from ffrt_trace_process import extract_process_id 23 24 25def extract_timestamp_str(log): 26 """ 27 extract timestamp(us) from trace line 28 """ 29 m = re.search(r" (\d+)\.(\d+): ", log) 30 if m is None: 31 return 0 32 33 match = m.group() 34 35 return match.strip()[:-1] 36 37 38def extract_cpu_id_str(log): 39 """ 40 extract #cpu from trace line 41 """ 42 m = re.search(r"\) \[.*\]", log) 43 if m is None: 44 return -1 45 46 match = m.group() 47 48 return match.split(']')[0].split('[')[-1] 49 50 51def make_costart_fake_log(mark, pid, label, gid, tid, tname, prio): 52 """ 53 when ffrt task start running, make a fake log that sched_switch from ffrt thread -> ffrt task 54 """ 55 timestamp = extract_timestamp_str(mark) 56 cpu_id = extract_cpu_id_str(mark) 57 fake_log = mark + "\n %s-%d (%7d) [%s] .... %s: sched_switch: prev_comm=%s prev_pid=%d prev_prio=%d prev_state=S ==> next_comm=%s next_pid=%d00%d next_prio=%d\n" % ( 58 tname, tid, pid, cpu_id, timestamp, tname, tid, prio, label, pid, gid, prio) 59 60 return fake_log 61 62 63def make_coyield_fake_log(mark, pid, label, gid, tid, tname, prio): 64 """ 65 when ffrt task leave running, make a fake log that sched_switch from ffrt task -> ffrt thread 66 """ 67 timestamp = extract_timestamp_str(mark) 68 cpu_id = extract_cpu_id_str(mark) 69 fake_log = " %s-%d00%d (%7d) [%s] .... %s: sched_switch: prev_comm=%s prev_pid=%d00%d prev_prio=%d prev_state=S ==> next_comm=%s next_pid=%d next_prio=%d\n" % ( 70 label, pid, gid, pid, cpu_id, timestamp, label, pid, gid, prio, tname, tid, prio) 71 72 if "|B|" in mark: 73 fake_log = " %s-%d00%d (%7d) [%s] .... %s: tracing_mark_write: E|%d\n" % \ 74 (label, pid, gid, pid, cpu_id, timestamp, pid) + fake_log 75 76 return fake_log 77 78 79def replace_sched_switch_log(fake_log, mark, pid, label, gid, tid): 80 """ 81 replace ffrt worker sched_swtich log with ffrt task 82 """ 83 if "prev_pid=%d" % tid in mark: 84 index = re.search("\(.+\)\s+\[\d", fake_log).span()[0] 85 fake_log = " %s-%d00%d " % (label, pid, gid) + fake_log[index:] 86 fake_log = fake_log[:fake_log.index("prev_comm=")] + "prev_comm=%s " % label + \ 87 fake_log[fake_log.index("prev_pid="):] 88 fake_log = fake_log[:fake_log.index("prev_pid=")] + "prev_pid=%d00%d " % (pid, gid) + \ 89 fake_log[fake_log.index("prev_prio="):] 90 elif "next_pid=%d" % tid in mark: 91 fake_log = fake_log[:fake_log.index("next_comm=")] + "next_comm=%s " % label + \ 92 fake_log[fake_log.index("next_pid="):] 93 fake_log = fake_log[:fake_log.index("next_pid=")] + "next_pid=%d00%d " % (pid, gid) + \ 94 fake_log[fake_log.index("next_prio="):] 95 96 return fake_log 97 98 99def replace_sched_wake_log(fake_log, label, pid, gid): 100 """ 101 replace ffrt worker sched_wake log with ffrt task 102 """ 103 fake_log = fake_log[:fake_log.index("comm=")] + "comm=%s " % label + fake_log[fake_log.index("pid="):] 104 fake_log = fake_log[:fake_log.index("pid=")] + "pid=%d00%d " % (pid, gid) + fake_log[fake_log.index("prio="):] 105 106 return fake_log 107 108 109def replace_sched_block_log(fake_log, pid, gid): 110 """ 111 replace ffrt worker sched_block log with ffrt task 112 """ 113 fake_log = fake_log[:fake_log.index("pid=")] + "pid=%d00%d " % (pid, gid) + fake_log[fake_log.index("iowait="):] 114 115 return fake_log 116 117 118def replace_tracing_mark_log(fake_log, label, pid, gid): 119 """ 120 replace ffrt worker normal tracing log with ffrt task 121 """ 122 index = re.search("\(.+\)\s+\[\d", fake_log).span()[0] 123 fake_log = " %s-%d00%d " % (label, pid, gid) + fake_log[index:] 124 125 return fake_log 126 127 128def convert_worker_log_to_task(mark, pid, label, gid, tid): 129 """ 130 convert ffrt worker trace logs to ffrt task trace logs 131 """ 132 fake_log = mark 133 134 if "sched_switch: " in mark: 135 return replace_sched_switch_log(fake_log, mark, pid, label, gid, tid) 136 137 if ": sched_wak" in mark: 138 return replace_sched_wake_log(fake_log, label, pid, gid) 139 140 if "sched_blocked_reason: " in mark: 141 return replace_sched_block_log(fake_log, pid, gid) 142 143 return replace_tracing_mark_log(fake_log, label, pid, gid) 144 145 146def find_ffrt_process_and_classify_logs(log, lineno, trace_map, ffrt_pids): 147 """ 148 find ffrt related process and threads (ffrtwk/ffrt_io), and classify logs for threads 149 """ 150 if "prev_comm=ffrt" in log: 151 pid = extract_process_id(log) 152 if pid not in ffrt_pids.keys(): 153 ffrt_pids[pid] = {} 154 tname = log[log.index("prev_comm="):].split("prev_pid=")[0].split('=')[-1].rstrip() 155 tid = int(log[log.index("prev_pid="):].split(' ')[0].split('=')[-1]) 156 if tid not in ffrt_pids[pid].keys(): 157 ffrt_pids[pid][tid] = {"name": tname, "logs": []} 158 159 if "sched_switch: " in log: 160 prev_tid = int(log[log.index("prev_pid="):].split(' ')[0].split('=')[-1]) 161 next_tid = int(log[log.index("next_pid="):].split(' ')[0].split('=')[-1]) 162 if prev_tid not in trace_map.keys(): 163 trace_map[prev_tid] = [] 164 trace_map[prev_tid].append(lineno) 165 if next_tid not in trace_map.keys(): 166 trace_map[next_tid] = [] 167 trace_map[next_tid].append(lineno) 168 return 169 170 if ": sched_wak" in log or "sched_blocked_reason: " in log: 171 tid = int(log[log.index("pid="):].split(' ')[0].split('=')[-1]) 172 if tid not in trace_map.keys(): 173 trace_map[tid] = [] 174 trace_map[tid].append(lineno) 175 return 176 177 match = re.search(" \(.+\)\s+\[\d", log) 178 if match is not None: 179 tid = int(log[:match.span()[0]].split('-')[-1]) 180 if tid not in trace_map.keys(): 181 trace_map[tid] = [] 182 trace_map[tid].append(lineno) 183 184 return 185 186 187def classify_logs_for_ffrt_worker(logs): 188 """ 189 split traces that written in the same line and classify logs based on ffrt worker 190 """ 191 trace_map = {} 192 ffrt_pids = {} 193 194 lineno = 0 195 while lineno < len(logs): 196 log = logs[lineno] 197 198 indexs = [m.span()[0] for m in re.finditer("\S+-\d+\s+\(", log)] 199 200 if len(indexs) > 1: 201 del logs[lineno] 202 for j in range(len(indexs)): 203 begin = indexs[j] 204 end = indexs[j + 1] if j + 1 < len(indexs) else len(log) 205 log_split = log[begin:end] 206 if j + 1 < len(indexs): 207 log_split = "%s\n" % log_split 208 logs.insert(lineno + j, log_split) 209 210 find_ffrt_process_and_classify_logs(logs[lineno + j], lineno + j, trace_map, ffrt_pids) 211 212 lineno += len(indexs) - 1 213 else: 214 find_ffrt_process_and_classify_logs(logs[lineno], lineno, trace_map, ffrt_pids) 215 216 lineno += 1 217 218 for pid, tids in ffrt_pids.items(): 219 for tid in tids.keys(): 220 ffrt_pids[pid][tid]["logs"] = trace_map[tid] 221 222 return ffrt_pids 223 224 225def convert_ffrt_thread_to_ffrt_task(logs, ffrt_pids): 226 """ 227 convert tracing mark of ffrt worker to ffrt task 228 """ 229 task_labels = {} 230 231 for pid, tids in ffrt_pids.items(): 232 task_labels[pid] = {} 233 for tid, info in ffrt_pids[pid].items(): 234 tname = info["name"] 235 linenos = info["logs"] 236 prio = 120 237 238 switch_in_fake_log = False 239 switch_out_fake_log = False 240 ffbk_mark_remove = False 241 task_running = None 242 for lineno in linenos: 243 mark = logs[lineno] 244 245 if "sched_switch: " in mark: 246 if "prev_pid=%d" % tid in mark: 247 prio = int(mark[mark.index("prev_prio="):].split(' ')[0].split('=')[-1]) 248 elif "next_pid=%d" % tid in mark: 249 prio = int(mark[mark.index("next_prio="):].split(' ')[0].split('=')[-1]) 250 251 # FFRT Task Running 252 if "FFRT::[" in mark: 253 label = mark.split('[')[-1].split(']')[0] 254 gid = int(mark.split('|')[-1]) 255 if gid not in task_labels[pid].keys(): 256 task_labels[pid][gid] = label 257 258 task_running = gid 259 fake_log = make_costart_fake_log(mark, pid, task_labels[pid][task_running], task_running, 260 tid, tname, prio) 261 logs[lineno] = fake_log 262 263 switch_in_fake_log = True 264 continue 265 266 if task_running is not None: 267 # Remove FFRT Supplemented Log for CoSwitch 268 if re.search(r" F\|(\d+)\|Co\|(\d+)", mark) is not None: 269 logs[lineno] = "\n" 270 if switch_in_fake_log is True: 271 switch_in_fake_log = False 272 continue 273 else: 274 switch_out_fake_log = True 275 continue 276 if switch_in_fake_log is True and "tracing_mark_write: B" in mark: 277 logs[lineno] = "\n" 278 continue 279 if switch_out_fake_log is True and "tracing_mark_write: E" in mark: 280 logs[lineno] = "\n" 281 continue 282 283 # FFRT Task Blocked/Finished Marks 284 if re.search(r" F\|(\d+)\|[BF]\|(\d+)", mark) is not None: 285 fake_log = make_coyield_fake_log(mark, pid, task_labels[pid][task_running], task_running, 286 tid, tname, prio) 287 logs[lineno] = fake_log 288 task_running = None 289 290 if switch_out_fake_log is True: 291 switch_out_fake_log = False 292 293 continue 294 295 if ffbk_mark_remove is True and "tracing_mark_write: E" in mark: 296 logs[lineno] = "\n" 297 ffbk_mark_remove = False 298 continue 299 300 fake_log = convert_worker_log_to_task(mark, pid, task_labels[pid][task_running], task_running, 301 tid) 302 303 # FFRT Blocked Reason 304 if "FFBK[" in fake_log: 305 if "[dep]" in fake_log: 306 fake_log = "\n" 307 elif "[chd]" in fake_log: 308 fake_log = "%sFFBK[wait_child]%s" % ( 309 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 310 elif "[dat]" in fake_log: 311 fake_log = "%sFFBK[wait_data]%s" % ( 312 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 313 elif "[fd]" in fake_log: 314 fake_log = "%sFFBK[wait_fd]%s" % ( 315 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 8:]) 316 elif "[mtx]" in fake_log: 317 fake_log = "%sFFBK[mutex]%s" % ( 318 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 319 elif "[slp]" in fake_log: 320 fake_log = "%sFFBK[sleep]%s" % ( 321 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 322 elif "[yld]" in fake_log: 323 fake_log = "%sFFBK[yield]%s" % ( 324 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 325 elif "[cnd]" in fake_log: 326 fake_log = "%sFFBK[cond_wait]%s" % ( 327 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 328 elif "[cnt]" in fake_log: 329 fake_log = "%sFFBK[cond_timedwait]%s" % ( 330 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 331 332 ffbk_mark_remove = True 333 334 logs[lineno] = fake_log 335 continue 336 337 return 338 339 340def supplement_ffrt_block_and_wake_info(logs): 341 """ 342 supplement ffrt block slice and link ffrt wake with ffrt block 343 """ 344 task_labels = {} 345 346 for lineno in range(len(logs)): 347 log = logs[lineno] 348 349 if "FFBK[" in log: 350 pid = extract_process_id(log) 351 gid = int(log.split('|')[-1]) 352 353 if pid not in task_labels.keys(): 354 task_labels[pid] = {} 355 if gid not in task_labels[pid].keys(): 356 task_labels[pid][gid] = { 357 "state": "none", 358 "prev_wake_lineno": None, 359 "prev_wake_log": None, 360 } 361 task_labels[pid][gid]["state"] = "block" 362 363 logs[lineno] = "%s\n" % logs[lineno][:logs[lineno].rfind('|')] 364 365 continue 366 367 if "FFWK|" in log: 368 pid = extract_process_id(log) 369 gid = int(log.split('|')[-1]) 370 371 if pid in task_labels.keys() and gid in task_labels[pid].keys(): 372 if task_labels[pid][gid]["state"] == "block": 373 timestamp = extract_timestamp_str(log) 374 cpu_id = extract_cpu_id_str(log) 375 ready_begin_log = " <...>-%d00%d (%7d) [%s] .... %s: tracing_mark_write: B|%d|FFREADY\n" % ( 376 pid, gid, pid, cpu_id, timestamp, pid) 377 logs[lineno] = ready_begin_log + logs[lineno] 378 379 task_labels[pid][gid]["state"] = "ready" 380 task_labels[pid][gid]["prev_wake_log"] = copy.copy(log) 381 task_labels[pid][gid]["prev_wake_lineno"] = lineno 382 383 continue 384 385 if "FFRT::[" in log: 386 pid = extract_process_id(log) 387 gid = int(log.split('\n')[0].split('|')[-1]) 388 389 if pid in task_labels.keys() and gid in task_labels[pid].keys(): 390 if task_labels[pid][gid]["state"] == "ready": 391 timestamp = extract_timestamp_str(log) 392 cpu_id = extract_cpu_id_str(log) 393 394 switch_log = log.split('\n')[-2] 395 task_comm = switch_log[switch_log.index("next_comm="):].split("next_pid=")[0].split('=')[ 396 -1].rstrip() 397 task_pid = int(switch_log[switch_log.index("next_pid="):].split(' ')[0].split('=')[-1]) 398 task_prio = int(switch_log[switch_log.index("next_prio="):].split('=')[-1]) 399 cpu_id_wake = extract_cpu_id_str(switch_log) 400 waking_log = task_labels[pid][gid]["prev_wake_log"][:task_labels[pid][gid]["prev_wake_log"].index( 401 "tracing_mark_write:")] + "sched_waking: comm=%s pid=%d prio=%d target_cpu=%s\n" % ( 402 task_comm, task_pid, task_prio, cpu_id_wake) 403 wakeup_log = task_labels[pid][gid]["prev_wake_log"][ 404 :task_labels[pid][gid]["prev_wake_log"].index("tracing_mark_write:")] + \ 405 "sched_wakeup: comm=%s pid=%d prio=%d target_cpu=%s\n" % ( 406 task_comm, task_pid, task_prio, cpu_id_wake) 407 logs[task_labels[pid][gid]["prev_wake_lineno"]] += waking_log + wakeup_log 408 409 ready_end_log = " <...>-%d00%d (%7d) [%s] .... %s: tracing_mark_write: E|%d\n" % ( 410 pid, gid, pid, cpu_id, timestamp, pid) 411 logs[lineno] = ready_end_log + logs[lineno] 412 413 task_labels[pid][gid]["state"] = "none" 414 415 continue 416 417 return 418 419 420def main(): 421 parser = argparse.ArgumentParser(description="parse") 422 parser.add_argument('--file', '-f', type=str, required=True, help="input trace file path") 423 424 args = parser.parse_args() 425 426 if not os.path.isfile(args.file): 427 exit(1) 428 429 with open(args.file, 'r', encoding="gb18030", errors="ignore") as infile: 430 logs = infile.readlines() 431 432 ffrt_pids = classify_logs_for_ffrt_worker(logs) 433 434 convert_ffrt_thread_to_ffrt_task(logs, ffrt_pids) 435 436 supplement_ffrt_block_and_wake_info(logs) 437 438 file_name, file_ext = os.path.splitext(args.file)[0], os.path.splitext(args.file)[1] 439 440 with os.fdopen(os.open("%s_ffrt_recover%s" % (file_name, file_ext), os.O_WRONLY | os.O_CREAT | os.O_TRUNC, 441 stat.S_IWUSR | stat.S_IRUSR), 'w', encoding="gb18030", errors="ignore") as outfile: 442 outfile.writelines(logs) 443 outfile.close() 444 445 infile.close() 446 447 return 448 449 450if __name__ == "__main__": 451 main()