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 copy 18import os 19import stat 20import re 21import argparse 22import csv 23import logging 24 25# global variables 26WORKER_KEY = ["ffrt_worker-", "ffrtwk", "ffrt_rtg-"] 27 28 29def extract_thread_name(log): 30 """ 31 extract thread name from trace line 32 """ 33 return log.strip().split(' ')[0] 34 35 36def extract_thread_id(log): 37 """ 38 extract tid from trace line 39 """ 40 if len(log.strip().split(' ')[0].split('-')) <= 1: 41 return 0 42 43 return int(log.strip().split(' ')[0].split('-')[-1]) 44 45 46def extract_process_id(log): 47 """ 48 extract pid from trace line 49 """ 50 m = re.search(r"\(\s*\d+\) \[", log) 51 if m is None: 52 return 0 53 54 match = m.group() 55 if '-' in match: 56 return 0 57 58 return int(match.split(')')[0].lstrip('(')) 59 60 61def extract_cpu_id(log): 62 """ 63 extract #cpu from trace line 64 """ 65 m = re.search(r"\) \[.*\]", log) 66 if m is None: 67 return -1 68 69 match = m.group() 70 71 return int(match.split(']')[0].split('[')[-1]) 72 73 74def extract_timestamp(log): 75 """ 76 extract timestamp(us) from trace line 77 """ 78 m = re.search(r" (\d+)\.(\d+): ", log) 79 if m is None: 80 return 0 81 82 match = m.group() 83 84 return int(match.strip().split('.')[0]) * int(1e6) + int(match.strip().rstrip(':').split('.')[-1]) 85 86 87def extract_trace_marker_task(log): 88 """ 89 extract ffrt task marker from trace line 90 """ 91 m = re.search(r" [FB]\|(\d+)\|(.+)\|(\d+)", log) 92 93 if m is not None: 94 match = m.group() 95 96 return (match.split('|')[-2], int(match.split('|')[-1])) 97 98 m = re.search(r" F\|(\d+)\|(\S+)\s(\d+)", log) 99 100 if m is not None: 101 match = m.group() 102 103 return (match.split('|')[-1].split(' ')[0], int(match.split(' ')[-1])) 104 105 return (False, False) 106 107 108def extract_switch_info(log): 109 """ 110 parse sched_switch log 111 """ 112 switch_info = {} 113 114 switch_info["cpu"] = extract_cpu_id(log) 115 switch_info["timestamp"] = extract_timestamp(log) 116 117 index = log.index("prev_comm=") 118 switch_info["prev_tname"] = log[index:].split("prev_pid=")[0].split('=')[-1].rstrip() 119 120 index = log.index("prev_pid=") 121 switch_info["prev_tid"] = int(log[index:].split(' ')[0].split('=')[-1]) 122 123 index = log.index("prev_state=") 124 switch_info["prev_state"] = log[index:].split(' ')[0].split('=')[-1] 125 126 index = log.index("next_comm=") 127 switch_info["next_tname"] = log[index:].split("next_pid=")[0].split('=')[-1].rstrip() 128 129 index = log.index("next_pid=") 130 switch_info["next_tid"] = int(log[index:].split(' ')[0].split('=')[-1]) 131 132 return switch_info 133 134 135def extract_active_pid_and_switch_log(logs): 136 """ 137 extract active processes in trace with corresponding switch logs 138 """ 139 active_process_map = {} 140 switch_log_map = {} 141 ffrt_process = [] 142 143 for log in logs: 144 if " sched_" in log or " tracing_mark_write" in log: 145 pid = extract_process_id(log) 146 if pid != 0 and pid not in active_process_map.keys(): 147 active_process_map[pid] = {} 148 149 tn = log[:log.find(" (")].strip() 150 ti = int(tn.split('-')[-1]) 151 if ti != 0 and ti not in active_process_map[pid].keys(): 152 active_process_map[pid][ti] = tn 153 154 if "sched_switch:" in log: 155 switch_info = extract_switch_info(log) 156 if switch_info["prev_tid"] not in switch_log_map.keys(): 157 switch_log_map[switch_info["prev_tid"]] = [] 158 switch_log_map[switch_info["prev_tid"]].append(switch_info) 159 160 if switch_info["next_tid"] not in switch_log_map.keys(): 161 switch_log_map[switch_info["next_tid"]] = [] 162 switch_log_map[switch_info["next_tid"]].append(switch_info) 163 164 if "ffrt" in switch_info["prev_tname"] and pid not in ffrt_process: 165 ffrt_process.append(pid) 166 167 if pid != 0 and switch_info["prev_tname"] not in active_process_map[pid][ti]: 168 active_process_map[pid][ti] = \ 169 "%s-%d" % (switch_info["prev_tname"], switch_info["prev_tid"]) 170 171 return ffrt_process, active_process_map, switch_log_map 172 173 174def parse_thread_trace(switch_logs, tid): 175 """ 176 parser trace record of specific thread： 177 1）sched_waking：waking up thread 178 2）sched_blocked_reason：uninterruptible sleep 179 3）sched_wakeup：thread waked up 180 4）sched_switch：thread switch out/in 181 note that trace file may lose some logs during recording 182 therefore approximate esimation is used in statistics 183 """ 184 statistics = { 185 "running": { 186 "duration": 0, "occurrence": 0, "average": 0. 187 }, 188 "cpu": {}, 189 "switch_out": {} 190 } 191 192 prev_timestamp = None 193 prev_running = None 194 195 for switch_log in switch_logs: 196 if switch_log["next_tid"] == tid: 197 statistics["running"]["occurrence"] += 1 198 if prev_running == "running": 199 continue 200 prev_timestamp = switch_log["timestamp"] 201 prev_running = "running" 202 elif switch_log["prev_tid"] == tid: 203 curr_timestamp = switch_log["timestamp"] 204 if prev_running == "running": 205 statistics["running"]["duration"] += curr_timestamp - prev_timestamp 206 if switch_log["cpu"] not in statistics["cpu"].keys(): 207 statistics["cpu"][switch_log["cpu"]] = 0 208 statistics["cpu"][switch_log["cpu"]] += curr_timestamp - prev_timestamp 209 prev_timestamp = curr_timestamp 210 prev_running = "idle" 211 if switch_log["prev_state"] not in statistics["switch_out"].keys(): 212 statistics["switch_out"][switch_log["prev_state"]] = 0 213 statistics["switch_out"][switch_log["prev_state"]] += 1 214 215 statistics["running"]["average"] = float(statistics["running"]["duration"]) / float( 216 statistics["running"]["occurrence"]) if statistics["running"]["occurrence"] != 0 else 0. 217 218 return statistics 219 220 221def generate_counter_info(suffix, task_records, next_status, gid, pid_counters_dict, pid): 222 """ 223 generate trace counter marker based on task status transition 224 """ 225 infos = [] 226 prev_counter = task_records[gid]["status"] + "_task" 227 next_counter = next_status + "_task" 228 229 if next_status != "finish": 230 pid_counters_dict[next_counter] += 1 231 info = suffix + "C|" + str(pid) + "|" + next_counter + "|" + str(pid_counters_dict[next_counter]) + '\n' 232 infos.append(info) 233 234 if next_status != "pending": 235 pid_counters_dict[prev_counter] -= 1 236 info = suffix + "C|" + str(pid) + "|" + prev_counter + "|" + str(pid_counters_dict[prev_counter]) + '\n' 237 infos.append(info) 238 239 task_records[gid]["status"] = next_status 240 241 return infos 242 243 244def parse_and_convert_task_trace(logs, pid): 245 """ 246 parser trace record of ffrt tasks： 247 P：task submit 248 R：task ready 249 E：task execute 250 B：task block 251 F：task execute finished 252 convert task execute record from async marker to sync marker 253 """ 254 task_records = {} 255 task_infos = {} 256 submit_no_ready_tasks = {} 257 ready_no_exec_tasks = {} 258 exec_no_done_tasks = {} 259 pid_counters_dict = { 260 'total_task': 0, 261 'pending_task': 0, 262 'ready_task': 0, 263 'running_task': 0, 264 'blocked_task': 0 265 } 266 267 pid_keyword = "%d) " % pid 268 trace_end_keyword = " E|%d" % pid 269 270 lineno = 0 271 remove_trace_end = False 272 logs_supplement = [] 273 for log in logs: 274 lineno += 1 275 276 if pid_keyword not in log or "tracing_mark_write: " not in log: 277 logs_supplement.append(log) 278 continue 279 280 if remove_trace_end is True and trace_end_keyword in log: 281 remove_trace_end = False 282 continue 283 284 task_marker = extract_trace_marker_task(log) 285 if len(task_marker) == 0 or task_marker[0] is False: 286 logs_supplement.append(log) 287 continue 288 289 state = task_marker[0] 290 if "H:" in state: 291 state = state[2:] 292 gid = task_marker[1] 293 suffix = log[:log.find("tracing_mark_write: ") + len("tracing_mark_write: ")] 294 295 if "P[" in state: 296 if gid not in task_records.keys(): 297 tag = state.split('[')[-1].split(']')[0] 298 task_records[gid] = { 299 "gid": gid, 300 "tag": tag, 301 "submit": extract_timestamp(log), 302 "ready": None, 303 "exec": None, 304 "cowait": [], 305 "costart": [], 306 "done": None, 307 "exec_duration": 0, 308 "cowait_duration": 0, 309 "exec_pids": [], 310 "prev_tname": None, 311 "status": "pending", 312 } 313 314 # replace async trace begin with trace counter 315 pid_counters_dict['total_task'] += 1 316 line_total_task = "%sC|%d|total_task|%s\n" % (suffix, pid, str(pid_counters_dict['total_task'])) 317 logs_supplement.append(line_total_task) 318 319 infos = generate_counter_info(suffix, task_records, "pending", gid, pid_counters_dict, pid) 320 for info in infos: 321 logs_supplement.append(info) 322 323 remove_trace_end = True 324 325 continue 326 327 if state == "R": 328 if gid in task_records.keys(): 329 if task_records[gid]["ready"] is None: 330 task_records[gid]["ready"] = extract_timestamp(log) 331 332 # replace async trace begin with trace counter 333 infos = generate_counter_info(suffix, task_records, "ready", gid, pid_counters_dict, pid) 334 for info in infos: 335 logs_supplement.append(info) 336 337 continue 338 339 if "FFRT::[" in state: 340 if gid in task_records.keys(): 341 timestamp = extract_timestamp(log) 342 tid = extract_thread_id(log) 343 if task_records[gid]["exec"] is None: 344 task_records[gid]["exec"] = timestamp 345 task_records[gid]["costart"].append(timestamp) 346 task_records[gid]["exec_pids"].append(tid) 347 task_records[gid]["prev_tname"] = extract_thread_name(log) 348 if len(task_records[gid]["cowait"]) > 0: 349 task_records[gid]["cowait_duration"] += task_records[gid]["costart"][-1] - task_records[gid]["cowait"][-1] 350 351 # replace async trace begin with trace counter 352 infos = generate_counter_info(suffix, task_records, "running", gid, pid_counters_dict, pid) 353 for info in infos: 354 logs_supplement.append(info) 355 logs_supplement.append(log) 356 357 continue 358 359 if state == "B": 360 if gid in task_records.keys(): 361 task_records[gid]["cowait"].append(extract_timestamp(log)) 362 if len(task_records[gid]["costart"]) > 0: 363 task_records[gid]["exec_duration"] += task_records[gid]["cowait"][-1] - task_records[gid]["costart"][-1] 364 365 # replace async trace begin with trace counter 366 infos = generate_counter_info(suffix, task_records, "blocked", gid, pid_counters_dict, pid) 367 for info in infos: 368 logs_supplement.append(info) 369 370 continue 371 372 if state == "F": 373 if gid in task_records.keys(): 374 timestamp = extract_timestamp(log) 375 task_records[gid]["done"] = timestamp 376 if len(task_records[gid]["costart"]) > 0: 377 task_records[gid]["exec_duration"] += timestamp - task_records[gid]["costart"][-1] 378 379 # replace async trace begin with trace counter 380 infos = generate_counter_info(suffix, task_records, "finish", gid, pid_counters_dict, pid) 381 for info in infos: 382 logs_supplement.append(info) 383 384 continue 385 386 logs_supplement.append(log) 387 388 for task in task_records.values(): 389 if task["tag"] not in task_infos.keys(): 390 task_infos[task["tag"]] = [] 391 392 # check suspect tasks, i.e. not ready, not execute, not finish 393 if task["ready"] is None: 394 if task["exec"] is not None or task["done"] is not None: 395 task["submit_ready"] = "lost" 396 else: 397 task["submit_ready"] = None 398 if task["tag"] not in submit_no_ready_tasks.keys(): 399 submit_no_ready_tasks[task["tag"]] = [] 400 submit_no_ready_tasks[task["tag"]].append(task["gid"]) 401 else: 402 task["submit_ready"] = task["ready"] - task["submit"] 403 404 if task["exec"] is None: 405 if task["ready"] is None: 406 task["ready_exec"] = None 407 elif task["done"] is not None: 408 task["ready_exec"] = "lost" 409 else: 410 task["ready_exec"] = None 411 if task["tag"] not in ready_no_exec_tasks.keys(): 412 ready_no_exec_tasks[task["tag"]] = [] 413 ready_no_exec_tasks[task["tag"]].append(task["gid"]) 414 else: 415 if task["ready"] is None: 416 task["ready_exec"] = "lost" 417 else: 418 task["ready_exec"] = task["exec"] - task["ready"] 419 420 if task["done"] is None: 421 task["exec_done"] = None 422 if task["exec"] is not None: 423 if task["tag"] not in exec_no_done_tasks.keys(): 424 exec_no_done_tasks[task["tag"]] = [] 425 exec_no_done_tasks[task["tag"]].append(task["gid"]) 426 else: 427 if task["exec"] is None: 428 task["exec_done"] = "lost" 429 else: 430 task["exec_done"] = task["done"] - task["exec"] 431 432 task_infos[task["tag"]].append(task) 433 434 return task_infos, submit_no_ready_tasks, ready_no_exec_tasks, exec_no_done_tasks, logs_supplement 435 436 437def process_trace(logs, pid, active_process_map, switch_log_map): 438 """ 439 process trace data, generate thread info and task info 440 """ 441 tids = list(active_process_map[pid].keys()) 442 tnames = list(active_process_map[pid].values()) 443 444 data = { 445 "total": {}, 446 "switch": { 447 "worker": {}, 448 "non-worker": {} 449 }, 450 "cpu": { 451 "worker": {}, 452 "non-worker": {} 453 }, 454 "thread": { 455 "worker": { 456 "S": {}, "T": {} 457 }, 458 "non-worker": { 459 "S": {}, "T": {} 460 }, 461 }, 462 "task": { 463 "infos": None, 464 "not_ready_tasks": None, 465 "not_exec_tasks": None, 466 "not_finish_taks": None 467 } 468 } 469 470 for i in range(len(tids)): 471 statistics = parse_thread_trace(switch_log_map[tids[i]], tids[i]) 472 473 tname = tnames[i] 474 ttype = "worker" if any([k in tname for k in WORKER_KEY]) else "non-worker" 475 476 # save thread slices 477 data["thread"][ttype]["S"][tname] = { 478 "statistics": statistics, 479 } 480 481 for cpu, duration in statistics["cpu"].items(): 482 if cpu not in data["cpu"][ttype].keys(): 483 data["cpu"][ttype][cpu] = 0 484 data["cpu"][ttype][cpu] += duration 485 486 # thread running distribution 487 if tname not in data["thread"][ttype]["T"].keys(): 488 data["thread"][ttype]["T"][tname] = 0 489 data["thread"][ttype]["T"][tname] += duration 490 491 for state, count in statistics["switch_out"].items(): 492 if state not in data["switch"][ttype].keys(): 493 data["switch"][ttype][state] = 0 494 data["switch"][ttype][state] += count 495 496 data["total"]["all_load"] = sum(data["thread"]["worker"]["T"].values()) + sum( 497 data["thread"]["non-worker"]["T"].values()) 498 data["total"]["worker_load"] = sum(data["thread"]["worker"]["T"].values()) 499 data["total"]["all_switch"] = sum(data["switch"]["worker"].values()) + sum( 500 data["switch"]["non-worker"].values()) 501 data["total"]["worker_switch"] = sum(data["switch"]["worker"].values()) 502 503 task_infos, submit_no_ready_tasks, ready_no_exec_tasks, exec_no_done_tasks, logs_supplement = \ 504 parse_and_convert_task_trace(logs, pid) 505 506 data["task"]["infos"] = task_infos 507 data["task"]["not_ready_tasks"] = submit_no_ready_tasks 508 data["task"]["not_exec_tasks"] = ready_no_exec_tasks 509 data["task"]["not_finish_taks"] = exec_no_done_tasks 510 511 return data, logs_supplement 512 513 514def write_infos(out_dir, logs, data): 515 """ 516 write process results 517 """ 518 if not os.path.exists(out_dir): 519 os.mkdir(out_dir) 520 else: 521 del_list = os.listdir(out_dir) 522 for f in del_list: 523 file_path = os.path.join(out_dir, f) 524 if os.path.isfile(file_path): 525 os.remove(file_path) 526 527 # write recovered trace 528 if logs is not None: 529 with os.fdopen( 530 os.open(out_dir + "/trace_refine.ftrace", os.O_WRONLY | os.O_CREAT | os.O_EXCL, stat.S_IWUSR | stat.S_IRUSR), 531 'w') as file: 532 file.writelines(logs) 533 file.close() 534 535 # write summary info 536 with os.fdopen( 537 os.open(out_dir + "/summary.txt", os.O_WRONLY | os.O_CREAT | os.O_EXCL, 538 stat.S_IWUSR | stat.S_IRUSR), 'w') as file: 539 lines = print_summary(data) 540 file.writelines(lines) 541 file.close() 542 543 # write thread info 544 for tname in data["thread"]["worker"]["S"].keys(): 545 with os.fdopen( 546 os.open("%s/%s.txt" % (out_dir, tname.replace("/", "_")), os.O_WRONLY | os.O_CREAT | os.O_EXCL, 547 stat.S_IWUSR | stat.S_IRUSR), 'w') as file: 548 statistics = data["thread"]["worker"]["S"][tname]["statistics"] 549 lines = print_hist(statistics) 550 file.writelines(lines) 551 552 switch = data["thread"]["worker"]["S"][tname]["statistics"]["switch_out"] 553 lines = print_switch(switch) 554 file.writelines(lines) 555 file.close() 556 557 # write task info 558 with os.fdopen(os.open(out_dir + "/task_info.csv", os.O_WRONLY | os.O_CREAT | os.O_EXCL, stat.S_IWUSR | stat.S_IRUSR), 'w', newline="") as file: 559 writer = csv.writer(file) 560 writer.writerow( 561 ["Label", "UID", "Submit_Timestamp", "Ready_Timestamp", "Exec_Timestamp", "Done_Timestamp", "Submit->Ready(us)", "Ready->Exec(us)", 562 "Exec->Done(us)", "Cowait_Occurence", "Cowait_Duration(us)", "Exec_Duration(us)", "Workers"]) 563 for task_name, task_info in data["task"]["infos"].items(): 564 for task in task_info: 565 writer.writerow([task_name, task["gid"], "%s.%s" % (str(task["submit"])[:-6], str(task["submit"])[-6:]), 566 "%s.%s" % (str(task["ready"])[:-6], str(task["ready"])[-6:]), 567 "%s.%s" % (str(task["exec"])[:-6], str(task["exec"])[-6:]), 568 "%s.%s" % (str(task["done"])[:-6], str(task["done"])[-6:]), str(task["submit_ready"]), 569 str(task["ready_exec"]), str(task["exec_done"]), len(task["cowait"]), 570 str(task["cowait_duration"]), str(task["exec_duration"]), 571 str(list(set(task["exec_pids"])))]) 572 file.close() 573 574 return 575 576 577def print_hist(s): 578 lines = [] 579 lines.append("State | Duration | Occurrence | Average\n") 580 lines.append("------------------------------------------------------------------------\n") 581 for itm in ["running"]: 582 if s[itm]["occurrence"] > 0: 583 lines.append("%-22s| %-13s us| %-16d| %.0f us\n" % ( 584 itm, str(s[itm]["duration"]), s[itm]["occurrence"], s[itm]["average"])) 585 lines.append("------------------------------------------------------------------------\n\n\n") 586 return lines 587 588 589def print_switch(w): 590 lines = [] 591 lines.append("Switch Type | Switch Times / Total Times\n") 592 lines.append("------------------------------------------------------\n") 593 t = sum(w.values()) 594 for k in w.keys(): 595 lines.append("%-22s| %10d / %-6d\n" % (k, w[k], t)) 596 lines.append("------------------------------------------------------\n\n\n") 597 return lines 598 599 600def print_task_info(task_name, tasks): 601 lines = [] 602 lines.append("Task Label: " + task_name + ", Total Count: " + str(len(tasks)) + "\n\n") 603 lines.append(" gid | submit_tstamp | submit_ready | ready_exec | exec_done | cowait_cnt | cowait_duration | exec_duration | exec_tids \n") 604 lines.append("-------------------------------------------------------------------------------------------------------------------------------------------------------------------\n") 605 606 for task in tasks: 607 timestamp = str(task["submit"]) 608 lines.append(" %-6d | %-12s | %-8sus | %-8sus | %-8sus | %-8d | %-10dus | %-10dus | %-48s\n" % ( 609 task["gid"], "%s.%s" % (timestamp[:-6], timestamp[-6:]), 610 str(task["submit_ready"]), str(task["ready_exec"]), str(task["exec_done"]), 611 len(task["cowait"]), task["cowait_duration"], task["exec_duration"], 612 str(list(set(task["exec_pids"]))))) 613 lines.append("-------------------------------------------------------------------------------------------------------------------------------------------------------------------") 614 return lines 615 616 617def print_summary(data): 618 lines = [] 619 620 lines.append("Summary:\n") 621 lines.append("\n1) Suspect Tasks:\n\n") 622 lines.append("tasks_not_ready:" + str(data["task"]["not_ready_tasks"]) + "\n") 623 lines.append("tasks_not_execute:" + str(data["task"]["not_exec_tasks"]) + "\n") 624 lines.append("tasks_not_finish:" + str(data["task"]["not_finish_taks"]) + "\n") 625 lines.append("\n------------------------------------------------------------------------------------------\n\n") 626 lines.append("2) Thread Overview:\n\n") 627 lines.append("%-16s | %3d worker | %3d non-worker | total |\n" % ( 628 "thread num", len(data["thread"]["worker"]["T"].keys()), len(data["thread"]["non-worker"]["T"].keys()))) 629 lines.append("%-16s | %3.0f%% | %3.0f%% | %-13d us |\n" % ( 630 "load ratio", 631 100.0 * data["total"]["worker_load"] / data["total"]["all_load"] if 632 data["total"]["all_load"] != 0 else 0, 633 100.0 * (data["total"]["all_load"] - data["total"]["worker_load"]) / data["total"]["all_load"] if 634 data["total"]["all_load"] != 0 else 0, 635 data["total"]["all_load"])) 636 lines.append("%-16s | %3.0f%% | %3.0f%% | %-14d |\n" % ( 637 "context switch", 638 100.0 * data["total"]["worker_switch"] / data["total"]["all_switch"] if 639 data["total"]["all_switch"] != 0 else 0, 640 100.0 * (data["total"]["all_switch"] - data["total"]["worker_switch"]) / data["total"]["all_switch"] if 641 data["total"]["all_switch"] != 0 else 0, 642 data["total"]["all_switch"])) 643 lines.append("\n------------------------------------------------------------------------------------------\n\n") 644 lines.append("3) CPU Usage:\n\n") 645 646 lines.append("cpu usage: worker\n") 647 for i in sorted(data["cpu"]["worker"].items(), key=lambda kv: (kv[1], kv[0]), reverse=True): 648 lines.append("%3.0f%% core %-3d %8d us\n" % ( 649 100.0 * i[1] / data["total"]["all_load"] if data["total"]["all_load"] != 0 else 0, i[0], i[1])) 650 lines.append("\ncpu usage: non-worker\n") 651 for i in sorted(data["cpu"]["non-worker"].items(), key=lambda kv: (kv[1], kv[0]), reverse=True): 652 lines.append("%3.0f%% core %-3d %8d us\n" % ( 653 100.0 * i[1] / data["total"]["all_load"] if data["total"]["all_load"] != 0 else 0, i[0], i[1])) 654 lines.append("\n------------------------------------------------------------------------------------------\n\n") 655 656 lines.append("4) Thread Distribution:\n\n") 657 lines.append("thread info: %d worker load distribution\n" % len(data["thread"]["worker"]["T"].keys())) 658 for i in sorted(data["thread"]["worker"]["T"].items(), key=lambda kv: (kv[1], kv[0]), reverse=True): 659 lines.append("%3.0f%% %-24s %8d us\n" % ( 660 100.0 * i[1] / data["total"]["all_load"] if data["total"]["all_load"] != 0 else 0, i[0], i[1])) 661 662 lines.append("\nthread info: %d non-worker load distribution\n" % len(data["thread"]["non-worker"]["T"].keys())) 663 for i in sorted(data["thread"]["non-worker"]["T"].items(), key=lambda kv: (kv[1], kv[0]), reverse=True): 664 lines.append("%3.0f%% %-24s %8d us\n" % ( 665 100.0 * i[1] / data["total"]["all_load"] if data["total"]["all_load"] != 0 else 0, i[0], i[1])) 666 lines.append("\n------------------------------------------------------------------------------------------\n\n") 667 668 return lines 669 670 671def clean_logs(logs): 672 """ 673 split logs that are mixed in same line 674 """ 675 num_line = len(logs) 676 677 i = 0 678 while i < num_line: 679 log = logs[i] 680 681 if " sched_" in log or " tracing_mark_write" in log: 682 match = re.finditer("\S+-\d+\s+\(", log) 683 indexs = [] 684 for m in match: 685 indexs.append(m.span()[0]) 686 if len(indexs) > 1: 687 del logs[i] 688 for j in range(len(indexs)): 689 begin = indexs[j] 690 end = indexs[j + 1] if j + 1 < len(indexs) else len(log) 691 logs.insert(i + j, log[begin:end]) 692 693 num_line += len(indexs) - 1 694 i += len(indexs) - 1 695 696 i += 1 697 698 return 699 700 701def main(): 702 parser = argparse.ArgumentParser(description="parse") 703 parser.add_argument('--file', '-f', type=str, required=True, help="input trace file path") 704 parser.add_argument('--pid', '-p', type=int, default=None, help="specify process id for trace analyzing") 705 706 args = parser.parse_args() 707 708 logging.basicConfig(filename="./ffrt_trace_process_log.txt", level=logging.DEBUG, 709 format="%(asctime)s - %(levelname)s - %(message)s", datefmt="%m/%d/%Y %H:%M:%S %p") 710 711 if not os.path.isfile(args.file): 712 logging.error("file: %s not exist", args.file) 713 exit(1) 714 715 with open(args.file, 'r', encoding="gb18030", errors="ignore") as file: 716 logs = file.readlines() 717 clean_logs(logs) 718 719 ffrt_process, active_process_map, switch_log_map = extract_active_pid_and_switch_log(logs) 720 721 if args.pid is None: 722 if len(ffrt_process) == 0: 723 logging.error("not find any process used ffrt automatically, plz assign -pid or -p in args") 724 exit(1) 725 pid = ffrt_process[0] 726 else: 727 pid = args.pid 728 729 if pid not in active_process_map.keys(): 730 logging.error("pid %d is not active in trace", pid) 731 exit(1) 732 733 data, logs_supplement = process_trace(logs, pid, active_process_map, switch_log_map) 734 logging.info("trace process done") 735 write_infos(args.file + "_result", logs_supplement, data) 736 logging.info("result saved in directory: %s", args.file) 737 738 file.close() 739 740 741if __name__ == '__main__': 742 main()