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=%d0%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-%d0%d (%7d) [%s] .... %s: sched_switch: prev_comm=%s prev_pid=%d0%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 or "|H:B " in mark: 73 fake_log = " %s-%d0%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-%d0%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=%d0%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=%d0%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=%d0%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=%d0%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-%d0%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 if "<faulted>" in logs[lineno + j]: 212 pid = extract_process_id(logs[lineno + j]) 213 logs[lineno + j] = logs[lineno + j][:logs[lineno + j].index("<faulted>")] + "E|%d\n" % pid 214 215 lineno += len(indexs) - 1 216 else: 217 find_ffrt_process_and_classify_logs(logs[lineno], lineno, trace_map, ffrt_pids) 218 if "<faulted>" in logs[lineno]: 219 pid = extract_process_id(logs[lineno]) 220 logs[lineno] = logs[lineno][:logs[lineno].index("<faulted>")] + "E|%d\n" % pid 221 222 lineno += 1 223 224 for pid, tids in ffrt_pids.items(): 225 for tid in tids.keys(): 226 ffrt_pids[pid][tid]["logs"] = trace_map[tid] 227 228 return ffrt_pids 229 230 231def convert_ffrt_thread_to_ffrt_task(logs, ffrt_pids): 232 """ 233 convert tracing mark of ffrt worker to ffrt task 234 """ 235 task_labels = {} 236 237 for pid, tids in ffrt_pids.items(): 238 task_labels[pid] = {} 239 for tid, info in ffrt_pids[pid].items(): 240 tname = info["name"] 241 linenos = info["logs"] 242 prio = 120 243 244 switch_in_fake_log = False 245 switch_out_fake_log = False 246 ffbk_mark_remove = False 247 task_running = None 248 for lineno in linenos: 249 mark = logs[lineno] 250 251 if "sched_switch: " in mark: 252 if "prev_pid=%d" % tid in mark: 253 prio = int(mark[mark.index("prev_prio="):].split(' ')[0].split('=')[-1]) 254 elif "next_pid=%d" % tid in mark: 255 prio = int(mark[mark.index("next_prio="):].split(' ')[0].split('=')[-1]) 256 257 # FFRT Task Running 258 if "FFRT::[" in mark: 259 miss_log = None 260 if task_running is not None: # trace end missing 261 miss_log = make_coyield_fake_log(mark, pid, task_labels[pid][task_running], task_running, 262 tid, tname, prio) 263 timestamp = extract_timestamp_str(mark) 264 cpu_id = extract_cpu_id_str(mark) 265 miss_log += " %s-%d (%7d) [%s] .... %s: tracing_mark_write: E|%d\n" % ( 266 tname, tid, pid, cpu_id, timestamp, pid) 267 268 label = mark.split('[')[-1].split(']')[0] 269 try: 270 gid = int(mark.split('|')[-1]) 271 except ValueError: 272 continue 273 if gid not in task_labels[pid].keys(): 274 task_labels[pid][gid] = label 275 276 task_running = gid 277 fake_log = make_costart_fake_log(mark, pid, task_labels[pid][task_running], task_running, 278 tid, tname, prio) 279 logs[lineno] = fake_log 280 281 if miss_log is not None: 282 logs[lineno] = miss_log + logs[lineno] 283 284 switch_in_fake_log = True 285 continue 286 287 if task_running is not None: 288 # Remove FFRT Supplemented Log for CoSwitch 289 if re.search(r" F\|(\d+)\|Co\|(\d+)", mark) is not None or \ 290 re.search(r" F\|(\d+)\|H:Co\s(\d+)", mark) is not None: 291 logs[lineno] = "\n" 292 if switch_in_fake_log is True: 293 switch_in_fake_log = False 294 continue 295 else: 296 switch_out_fake_log = True 297 continue 298 if switch_in_fake_log is True and "tracing_mark_write: B" in mark: 299 logs[lineno] = "\n" 300 continue 301 if switch_out_fake_log is True and "tracing_mark_write: E" in mark: 302 logs[lineno] = "\n" 303 continue 304 305 # FFRT Task Blocked/Finished Marks 306 if re.search(r" F\|(\d+)\|[BF]\|(\d+)", mark) is not None or \ 307 re.search(r" F\|(\d+)\|H:[BF]\s(\d+)", mark) is not None: 308 fake_log = make_coyield_fake_log(mark, pid, task_labels[pid][task_running], task_running, 309 tid, tname, prio) 310 logs[lineno] = fake_log 311 task_running = None 312 313 if switch_out_fake_log is True: 314 switch_out_fake_log = False 315 316 continue 317 318 if ffbk_mark_remove is True and "tracing_mark_write: E" in mark: 319 logs[lineno] = "\n" 320 ffbk_mark_remove = False 321 continue 322 323 fake_log = convert_worker_log_to_task(mark, pid, task_labels[pid][task_running], task_running, 324 tid) 325 326 # FFRT Blocked Reason 327 if "FFBK[" in fake_log: 328 if "[dep]" in fake_log: 329 fake_log = "\n" 330 elif "[chd]" in fake_log: 331 fake_log = "%sFFBK[wait_child]%s" % ( 332 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 333 elif "[dat]" in fake_log: 334 fake_log = "%sFFBK[wait_data]%s" % ( 335 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 336 elif "[fd]" in fake_log: 337 fake_log = "%sFFBK[wait_fd]%s" % ( 338 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 8:]) 339 elif "[mtx]" in fake_log: 340 fake_log = "%sFFBK[mutex]%s" % ( 341 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 342 elif "[slp]" in fake_log: 343 fake_log = "%sFFBK[sleep]%s" % ( 344 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 345 elif "[yld]" in fake_log: 346 fake_log = "%sFFBK[yield]%s" % ( 347 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 348 elif "[cnd]" in fake_log: 349 fake_log = "%sFFBK[cond_wait]%s" % ( 350 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 351 elif "[cnt]" in fake_log: 352 fake_log = "%sFFBK[cond_timedwait]%s" % ( 353 fake_log[:fake_log.index("FFBK[")], fake_log[fake_log.index("FFBK[") + 9:]) 354 355 ffbk_mark_remove = True 356 357 logs[lineno] = fake_log 358 continue 359 360 return 361 362 363def supplement_ffrt_block_and_wake_info(logs): 364 """ 365 supplement ffrt block slice and link ffrt wake with ffrt block 366 """ 367 task_labels = {} 368 369 for lineno in range(len(logs)): 370 log = logs[lineno] 371 372 if "FFBK[" in log: 373 pid = extract_process_id(log) 374 gid = int(log.split('|')[-1]) 375 376 if pid not in task_labels.keys(): 377 task_labels[pid] = {} 378 if gid not in task_labels[pid].keys(): 379 task_labels[pid][gid] = { 380 "state": "none", 381 "prev_wake_lineno": None, 382 "prev_wake_log": None, 383 } 384 385 ready_end_log = None 386 if task_labels[pid][gid]["state"] == "ready": # abnormal scene: ready -> block, running missed 387 timestamp = extract_timestamp_str(log) 388 cpu_id = extract_cpu_id_str(log) 389 ready_end_log = " <...>-%d0%d (%7d) [%s] .... %s: tracing_mark_write: E|%d\n" % ( 390 pid, gid, pid, cpu_id, timestamp, pid) 391 392 task_labels[pid][gid]["state"] = "block" 393 394 logs[lineno] = "%s\n" % logs[lineno][:logs[lineno].rfind('|')] 395 396 if ready_end_log is not None: 397 logs[lineno] = ready_end_log + logs[lineno] 398 399 continue 400 401 if "FFWK|" in log: 402 pid = extract_process_id(log) 403 gid = int(log.split('|')[-1]) 404 405 if pid in task_labels.keys() and gid in task_labels[pid].keys(): 406 timestamp = extract_timestamp_str(log) 407 cpu_id = extract_cpu_id_str(log) 408 if "H:FFWK" in log: 409 ready_begin_log = " <...>-%d0%d (%7d) [%s] .... %s: tracing_mark_write: B|%d|H:FFREADY\n" % ( 410 pid, gid, pid, cpu_id, timestamp, pid) 411 else: 412 ready_begin_log = " <...>-%d0%d (%7d) [%s] .... %s: tracing_mark_write: B|%d|FFREADY\n" % ( 413 pid, gid, pid, cpu_id, timestamp, pid) 414 logs[lineno] = ready_begin_log + logs[lineno] 415 416 if task_labels[pid][gid]["state"] == "ready": # abnormal scene: ready -> ready, running & block missed 417 logs[task_labels[pid][gid]["prev_wake_lineno"]] = logs[task_labels[pid][gid]["prev_wake_lineno"]][ 418 logs[task_labels[pid][gid][ 419 "prev_wake_lineno"]].index("FFREADY") + 8:] 420 421 task_labels[pid][gid]["state"] = "ready" 422 task_labels[pid][gid]["prev_wake_log"] = copy.copy(log) 423 task_labels[pid][gid]["prev_wake_lineno"] = lineno 424 425 continue 426 427 if "FFRT::[" in log: 428 pid = extract_process_id(log) 429 try: 430 gid = int([e for e in log.split('\n') if "FFRT::[" in e][0].split('|')[-1]) 431 except ValueError: 432 continue 433 434 if pid in task_labels.keys() and gid in task_labels[pid].keys(): 435 if task_labels[pid][gid]["state"] == "ready": 436 timestamp = extract_timestamp_str(log) 437 cpu_id = extract_cpu_id_str(log) 438 439 switch_log = log.split('\n')[-2] 440 task_comm = switch_log[switch_log.index("next_comm="):].split("next_pid=")[0].split('=')[ 441 -1].rstrip() 442 task_pid = int(switch_log[switch_log.index("next_pid="):].split(' ')[0].split('=')[-1]) 443 task_prio = int(switch_log[switch_log.index("next_prio="):].split('=')[-1]) 444 cpu_id_wake = extract_cpu_id_str(switch_log) 445 waking_log = task_labels[pid][gid]["prev_wake_log"][:task_labels[pid][gid]["prev_wake_log"].index( 446 "tracing_mark_write:")] + "sched_waking: comm=%s pid=%d prio=%d target_cpu=%s\n" % ( 447 task_comm, task_pid, task_prio, cpu_id_wake) 448 wakeup_log = task_labels[pid][gid]["prev_wake_log"][ 449 :task_labels[pid][gid]["prev_wake_log"].index("tracing_mark_write:")] + \ 450 "sched_wakeup: comm=%s pid=%d prio=%d target_cpu=%s\n" % ( 451 task_comm, task_pid, task_prio, cpu_id_wake) 452 logs[task_labels[pid][gid]["prev_wake_lineno"]] += waking_log + wakeup_log 453 454 ready_end_log = " <...>-%d0%d (%7d) [%s] .... %s: tracing_mark_write: E|%d\n" % ( 455 pid, gid, pid, cpu_id, timestamp, pid) 456 logs[lineno] = ready_end_log + logs[lineno] 457 458 task_labels[pid][gid]["state"] = "none" 459 460 continue 461 462 return 463 464 465def trace_recover(file): 466 with open(file, 'r', encoding="gb18030", errors="ignore") as infile: 467 logs = infile.readlines() 468 469 ffrt_pids = classify_logs_for_ffrt_worker(logs) 470 471 convert_ffrt_thread_to_ffrt_task(logs, ffrt_pids) 472 473 supplement_ffrt_block_and_wake_info(logs) 474 475 file_name, file_ext = os.path.splitext(file)[0], os.path.splitext(file)[1] 476 477 with os.fdopen(os.open("%s_ffrt_recover%s" % (file_name, file_ext), os.O_WRONLY | os.O_CREAT | os.O_TRUNC, 478 stat.S_IWUSR | stat.S_IRUSR), 'w', encoding="gb18030", errors="ignore") as outfile: 479 outfile.writelines(logs) 480 outfile.close() 481 482 infile.close() 483 484 return 485 486 487def main(): 488 parser = argparse.ArgumentParser(description="parse") 489 parser.add_argument('--file', '-f', type=str, required=True, help="input trace file path") 490 491 args = parser.parse_args() 492 493 if not os.path.isfile(args.file): 494 exit(1) 495 496 trace_recover(args.file) 497 498 return 499 500 501if __name__ == "__main__": 502 main()