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