• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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()